Testing a function that generates logs
Tags: go, tdd, unittest, log
Published: 2020-07-20 02:54:13

*"Choosing the right limitations for a certain problem domain is often much more powerful that allowing anything."* - Jason Moiron

## Problem

Sometimes, I mean, only when it is strictly needed, we need to verify that our application is generating expected logs. So, the question here is, how can I test that?

Below is the model for our log mechanism.

![Alt Text](https://dev-to-uploads.s3.amazonaws.com/i/tt9ymhl3k347hkq9uv8l.png)

For this scenario, `Service#AddPet()` will print three logs that we expect to see in the output. Suppose we will be using `JSON` format for the Logs, then the result might be something like this:

```json
{"action": "petstoreapp.Service.AddPet", "msg": "adding new pet", "pet": {"Family": "Dog", "Race": "Coker"}, "id": "1"}

{"action": "petstoreapp.Service.AddPet", "msg": "storing new pet", "pet": {"Family": "Dog", "Race": "Coker"}, "id": "1"}

{"action": "petstoreapp.Service.AddPet", "msg": "notifying new pet", "pet": {"Family": "Dog", "Race": "Coker"}, "id": "1"}
```

## Solution

[1.] First, write the unit test we imagine. Note that it is also the solution to this problem.

```go
package petstoreapp_test

import (
	"context"
	"testing"

	"github.com/group/project/pkg/petstoreapp"
	"github.com/stretchr/testify/assert"
)

func TestAddPetLogs(t *testing.T) {
	// GIVEN
	newPet := petstoreapp.Pet{
		Family: "Dog",
		Race:   "Coker",
	}
	expectedLog := [][]interface{}{
		{
			"action", "petstoreapp.Service.AddPet",
			"msg", "adding new pet",
			"pet", petstoreapp.Pet{Family: "Dog", Race: "Coker"},
			"id", "1",
		},
		{
			"action", "petstoreapp.Service.AddPet",
			"msg", "storing new pet",
			"pet", petstoreapp.Pet{Family: "Dog", Race: "Coker"},
			"id", "1",
		},
		{
			"action", "petstoreapp.Service.AddPet",
			"msg", "notifying new pet",
			"pet", petstoreapp.Pet{Family: "Dog", Race: "Coker"},
			"id", "1",
		},
	}
	ctx := context.TODO()
	logger := newLoggerMock()
	idGenerator := idGeneratorMock("1")
	petstoreService := petstoreapp.NewService(idGenerator, logger)
	// WHEN
	_, err := petstoreService.AddPet(ctx, newPet)
	// THEN
	if err != nil {
		t.Errorf("unexpected error: %s", err)
	}
	assert.Equal(t, expectedLog, logger.logs)
}
```
Main points.

*  We have an `expectedLog` variable with the list of parameters we will receive in the logs.
*  We pass the Mock Logger to the service instance.
*  We verify that the logs generated in the `AddPet()` function are equal to the value of `expectedLog`.

[2.] Create the logger mock.

```go
package petstoreapp_test

// loggerMock
type loggerMock struct {
	logs [][]interface{}
}

func newLoggerMock() *loggerMock {
	return &loggerMock{
		logs: [][]interface{}{},
	}
}

// Log add given parameters to the internal log slice
func (l *loggerMock) Log(v ...interface{}) {
	l.logs = append(l.logs, v)
}
```

[3.] Once our unit test is ready, we write the service `AddPet()` function.

```go
package petstoreapp

import "context"

// Service defines behavior to save a pet.
type Service struct {
	logger      Logger
	idGenerator IDGenerator
}

// NewService creates a new petstore service.
func NewService(idGenerator IDGenerator, logger Logger) *Service {
	return &Service{
		logger:      logger,
		idGenerator: idGenerator,
	}
}

// AddPet add the given new pet and returns its id or an error if something
// goes wrong.
func (s *Service) AddPet(ctx context.Context, newPet Pet) (string, error) {
	petID := s.idGenerator.Generate()
	s.logger.Log("action", "petstoreapp.Service.AddPet", "msg", "adding new pet", "pet", newPet, "id", petID)
	// do some logic to persist the new pet
	s.logger.Log("action", "petstoreapp.Service.AddPet", "msg", "storing new pet", "pet", newPet, "id", petID)
	// do some logic to notify the creation of the new pet
	s.logger.Log("action", "petstoreapp.Service.AddPet", "msg", "notifying new pet", "pet", newPet, "id", petID)
	return petID, nil
}
```

[4.] Now execute the unit test to see it is working well.

```sh
go test -timeout 30s github.com/group/project/pkg/petstoreapp -run ^TestAddPetLogs$

ok  	github.com/group/project/pkg/petstoreapp
```


## Conclusion

* Most of the Logger mechanisms have a `Log()` function that receives a list of parameters to print.
* Remember that we should verify that we are sending the expected values ​​to the Logger and not the way it is printed in the output mechanism.
* Dependency Inversion Principle: **"Program to an interface, not to an implementation"**.
* In the unit test, we should have a Mock for the Logger in order to catch the expected parameters.


## Acknowledgement

* For modeling I was using [PlantUML](https://plantuml.com)
* For testing assertions I use this library [Testify](https://github.com/stretchr/testify)