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

Blog

Testing a function that generates logs

Fernando Ocampo

Problem

Solution

Conclusion

Acknowledgement

Join Our Newsletter. No Spam, Only the good stuff.

Related