Testing a function that generates logs

"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.

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:

{"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.

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.

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.

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.

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
• For testing assertions I use this library Testify