Forem: Fernando Ocampo

Logging an application in Go

Fernando Ocampo — Mon, 10 Aug 2020 05:00:30 +0000

"If you don’t write it down, it never happened." - Tom Clancy

Context

Proper logging allows you to keep track of what happens with the logic of your application and with that you can even avoid using debugging tools.

Problem

We can list some visible problems in our application.

Errors are difficult to track.
All the time we need to use debugging tools to find errors or understand behavior.
Errors root causes are unknown.
The application doesn't recommend me how to fix errors.

Solution

Well the obvious solution for this problem is the logger mechanism, so I want to show you an useful implementation.

Let's look at the model of this scenario.

Now imagine you have a unit-test where you want to test the creation of a new employee.

package application_test

import (
    "bytes"
    "context"
    "errors"
    "log"
    "testing"

    "github.com/group/project/pkg/application"
    "github.com/group/project/pkg/domain"
    "github.com/group/project/pkg/logging"
)

func TestNewEmployee(t *testing.T) {
    // GIVEN
    newEmployee := domain.NewEmployee{
        FirstName: "William",
        LastName:  "Wallace",
    }
    loggerBuffer := new(bytes.Buffer)
    repository := newRepositoryMock(nil)
    employeeLogger := logging.NewWithWriter(logging.Logrus, "application.EmployeeService", logging.Debug, loggerBuffer)
    service := application.NewEmployeeService(repository, employeeLogger)
    // WHEN
    newID, err := service.Create(context.TODO(), newEmployee)
    // THEN
    if err != nil {
        log.Println(loggerBuffer.String())
        t.Errorf("unexpected error: %s", err)
        t.FailNow()
    }
    if len(newID) < 1 {
        log.Println(loggerBuffer.String())
        t.Error("empty ID is not expected")
    }
}

The unit test purposely fails to see the goodness of the logs. Maybe you wonder, but why? all the data is there, but when we check the logs we found the following.

go test -timeout 30s -run ^TestNewEmployee$

2020/08/08 13:28:55 {"artifact":"application.EmployeeService","level":"debug","method":"NewEmployeeService","msg":"creating employee service","time":"2020-08-08T13:28:55-05:00"}
{"artifact":"application.EmployeeService","level":"debug","method":"Create","msg":"creating employee","new employee":{"FirstName":"William","LastName":"Wallace","Email":""},"time":"2020-08-08T13:28:55-05:00"}

--- FAIL: TestNewEmployee (0.00s)
    project/pkg/application/employee_test.go:54: unexpected error: the data of the new employee is not valid: email is mandatory

Then when looking at the logs, you will see that the email was empty.

{"artifact":"application.EmployeeService","level":"debug","method":"Create","msg":"creating employee","new employee":{"FirstName":"William","LastName":"Wallace","Email":""},"time":"2020-08-08T13:28:55-05:00"}

To achieve this, I followed this philosophy.

Handling an error means:

The error has been logged.

The application is back to 100% integrity.

The current error is not reported any longer.

William Kennedy

Let's look at this current implementation in core logic. Specifically the Create method.

employee service

package application

import (
    "context"

    "github.com/group/project/pkg/domain"
    "github.com/group/project/pkg/logging"
    "github.com/google/uuid"
    "github.com/pkg/errors"
)

// EmployeeService defines basic logic to store employee data.
type EmployeeService struct {
    logger     logging.Logger
    repository Repository
}

// NewEmployeeService creates a new EmployeeService instance.
func NewEmployeeService(repository Repository, logger logging.Logger) *EmployeeService {
    logger.Debug("creating employee service", logging.Fields{"method": "NewEmployeeService"})
    return &EmployeeService{
        logger:     logger,
        repository: repository,
    }
}

// Create creates a new employee with the given data.
// Returns the ID generated or an error if something goes wrong.
func (e *EmployeeService) Create(ctx context.Context, newEmployee domain.NewEmployee) (string, error) {
    e.logger.Debug("creating employee", logging.Fields{"method": "Create", "new employee": newEmployee})
    validationError := newEmployee.Validate()
    if validationError != nil {
        return "", errors.Wrap(validationError, "the data of the new employee is not valid")
    }
    newEmployeeID := uuid.New().String()
    e.logger.Debug("new employee id is generated", logging.Fields{"method": "Create", "id": newEmployeeID})
    employee := newEmployee.ToEmployee(newEmployeeID)
    e.logger.Info("storing employee", logging.Fields{"method": "Create", "employee": employee})
    err := e.repository.Save(ctx, employee)
    if err != nil {
        e.logger.Error(
            "employee cannot be stored",
            logging.Fields{
                "method":   "Create",
                "error":    err,
                "employee": employee,
            },
        )
        return "", errors.New("employee cannot be stored")
    }
    return newEmployeeID, nil
}

I used debug to track the flow of the application and show fine-grained data in favor of debugging.
With the info level I log what may be of interest to administrators and show the progress of the application.
Level of error only if the function will handle the error; otherwise I returned it to the calling function.

In the business logic of the employee service, I was forced to return an error to tell the upper layer that the new employee could not be created.

Another important thing to note here is the use of logging.Fields type. My purpose is to add context to the logs, in a key/value way. This will be helpful for admins and log administration tools to identify future issues.

My logger artifact, as you saw in the previous model, is an interface to decouple any existing logging mechanism.

package logging

import "io"

// Logger defines behavior for logger mechanism.
type Logger interface {
    // Debug log with debug level
    Debug(message string, fields Fields)
    // Info log with info level
    Info(message string, fields Fields)
    // Warn log with warn level
    Warn(message string, fields Fields)
    // Error log with error level
    Error(message string, fields Fields)
}

// New creates a new logger with standard output.
func New(selectedLogger Type, artifactName string, level Level) Logger {
    switch selectedLogger {
    case Basic:
        return NewBasicLoggerWithStdout(artifactName, level)
    case Logrus:
        return NewLogrusLoggerWithStdout(artifactName, level)
    default:
        return NewBasicLoggerWithStdout(artifactName, level)
    }
}

// NewWithWriter creates a new logger with the given output mechanism.
func NewWithWriter(selectedLogger Type, artifactName string, level Level, writer io.Writer) Logger {
    switch selectedLogger {
    case Basic:
        return NewBasicLogger(artifactName, level, writer)
    case Logrus:
        return NewLogrusLogger(artifactName, level, writer)
    default:
        return NewBasicLoggerWithStdout(artifactName, level)
    }
}

I've created an interface to define the behavior of the logger in my application, as I mentioned, this will create a level of indirection between my business logic and these kinds of mechanisms.

One of the loggers used is the logrus library. Below you can check the logrus logger implementation.

package logging

import (
    "io"
    "os"

    "github.com/sirupsen/logrus"
)

// logrusLogger contains a logrus logger.
type logrusLogger struct {
    // level log level
    level Level
    // artifact is the name of the artifact that print the log.
    artifact string
    // logger is the logrus logger.
    logger *logrus.Logger
}

// NewLogrusLoggerWithStdout create a logrus logger with stdout output.
func NewLogrusLoggerWithStdout(artifactName string, level Level) Logger {
    return NewLogrusLogger(artifactName, level, os.Stdout)
}

// NewLogrusLogger create a logrus logger.
func NewLogrusLogger(artifactName string, level Level, output io.Writer) Logger {
    logger := logrus.New()
    logger.SetOutput(output)
    logger.SetLevel(getLogrusLevel(level))
    logger.SetFormatter(&logrus.JSONFormatter{})
    // logger = logger.WithField(artifactField, artifactName)
    return &logrusLogger{
        level:    level,
        logger:   logger,
        artifact: artifactName,
    }
}

func (l *logrusLogger) Debug(message string, fields Fields) {
    if l.level&Debug != 0 {
        l.logger.WithField(artifactField, l.artifact).
            WithFields(logrus.Fields(fields)).
            Debug(message)
    }
}

func (l *logrusLogger) Info(message string, fields Fields) {
    if l.level&(Debug|Info) != 0 {
        l.logger.WithField(artifactField, l.artifact).
            WithFields(logrus.Fields(fields)).
            Info(message)
    }
}

func (l *logrusLogger) Warn(message string, fields Fields) {
    if l.level&(Debug|Info|Warn) != 0 {
        l.logger.WithField(artifactField, l.artifact).
            WithFields(logrus.Fields(fields)).
            Warn(message)
    }
}

func (l *logrusLogger) Error(message string, fields Fields) {
    if l.level&(Debug|Info|Warn|Error) != 0 {
        l.logger.WithField(artifactField, l.artifact).
            WithFields(logrus.Fields(fields)).
            Error(message)
    }
}

// getLogrusLevel get the logrus level based on allowed levels.
func getLogrusLevel(level Level) logrus.Level {
    switch level {
    case Debug:
        return logrus.DebugLevel
    case Info:
        return logrus.InfoLevel
    case Warn:
        return logrus.WarnLevel
    case Error:
        return logrus.ErrorLevel
    default:
        return logrus.DebugLevel
    }
}

Finally, when you run the application at the debug level, creating an employee will print these logs.

{"artifact":"usefullog.main","level":"info","msg":"starting usefullog application","time":"2020-08-09T09:09:33-05:00"}
{"artifact":"repository.AnyStorage","level":"debug","method":"NewAnyStorage","msg":"creating any storage repository","time":"2020-08-09T09:09:33-05:00"}
{"artifact":"application.EmployeeService","level":"debug","method":"NewEmployeeService","msg":"creating employee service","time":"2020-08-09T09:09:33-05:00"}
{"artifact":"application.EmployeeService","level":"debug","method":"Create","msg":"creating employee","new employee":{"FirstName":"Fernando","LastName":"Ocampo","Email":"fernando.ocampo@dev.to"},"time":"2020-08-09T09:09:33-05:00"}
{"artifact":"application.EmployeeService","id":"79950d93-3298-4d79-8aa0-d71e717bfba5","level":"debug","method":"Create","msg":"new employee id is generated","time":"2020-08-09T09:09:33-05:00"}
{"artifact":"application.EmployeeService","employee":{"ID":"79950d93-3298-4d79-8aa0-d71e717bfba5","FirstName":"Fernando","LastName":"Ocampo","Email":"fernando.ocampo@dev.to"},"level":"info","method":"Create","msg":"storing employee","time":"2020-08-09T09:09:33-05:00"}
{"artifact":"repository.AnyStorage","level":"info","method":"Save","msg":"storing employee","new employee":{"ID":"79950d93-3298-4d79-8aa0-d71e717bfba5","FirstName":"Fernando","LastName":"Ocampo","Email":"fernando.ocampo@dev.to"},"time":"2020-08-09T09:09:33-05:00"}
{"artifact":"repository.AnyStorage","employee":{"ID":"79950d93-3298-4d79-8aa0-d71e717bfba5","FirstName":"Fernando","LastName":"Ocampo","Email":"fernando.ocampo@dev.to"},"level":"info","method":"Save","msg":"employee was stored succesfully","time":"2020-08-09T09:09:33-05:00"}
{"artifact":"usefullog.main","id":"79950d93-3298-4d79-8aa0-d71e717bfba5","level":"info","msg":"employee was created successfully","time":"2020-08-09T09:09:33-05:00"}

If you want to see more details about this suggestion please check this article repository.

Conclusion

Make it easier to find errors.
Logs help to debug my application.
Logs allow us to know the root causes of errors.
Logs should give feedback how to solve errors.
You can continue improving you log mechanism in your app.
If you feel your log mechanism can change in the near future, create an abstraction of the logger.
Successful tests should not print anything.
If you like this philosophy, follow William Kennedy philosophy about logging and errors.

Acknowledgement

For modeling I was using PlantUML
For testing assertions I use this library Testify
Log levels reference with log4j in my old Java experience.

Testing a function that generates logs

Fernando Ocampo — Mon, 20 Jul 2020 02:54:13 +0000

"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

Testing a function that calls a goroutine

Fernando Ocampo — Sun, 19 Jul 2020 03:47:10 +0000

"If you are using a third party framework to generate SQL your TDD tests should check that the framework is being called correctly." - Uncle Bob

Problem

Creating unit tests where there is concurrency can become complicated if we do not take special care. In this article, we are going to show a simple scenario, but it could take us a few minutes to figure out how to do it. It occurs when we want to create an unit test for a function that internally calls another library asynchronously.

Let's look at the model of this scenario.

now take a look at the notification unit test

We created a basicService with the mock notifier and called the Add() function to verify that the expected message has been sent to the emailNotifierMock.



import (
    "context"
    "testing"

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

func TestEmailNotification(t *testing.T) {
    // GIVEN
    newEmployee := employeeapp.Employee{
        FirstName: "Daenerys",
        LastName:  "Targaryen",
        Email:     "someone@somewhere.com",
        Salary:    25000,
    }
    expectedMessage := employeeapp.Message{
        Subject: "Hey",
        To:      "someone@somewhere.com",
        From:    "anybody@somewhere.com",
        Body:    "Good morning there",
    }
    ctx := context.TODO()
    emailNotifier := NewEmailNotifierMock()
    basicService := employeeapp.NewBasicService(emailNotifier)

    // WHEN
    _, err := basicService.Add(ctx, newEmployee)
    // THEN
    if err != nil {
        t.Errorf("no error was expected but got: %q", err)
    }

    assert.Equal(t, expectedMessage, emailNotifier.messages[0])
}

For the notifier dependency, we have created emailNotifierMock below.



// emailNotifierMock is a Notifier mock that track
// received messages
type emailNotifierMock struct {
    messages []employeeapp.Message
}

func NewEmailNotifierMock() *emailNotifierMock {
    return &emailNotifierMock{
        messages: make([]employeeapp.Message, 0),
    }
}

// Notify adds the given message to the messages map contained in the mock.
func (e *emailNotifierMock) Notify(ctx context.Context, message employeeapp.Message) error {
    e.messages = append(e.messages, message)
    return nil
}

If you run the unit test, the result will be successful.



go test -timeout 30s github.com/group/project/pkg/employeeapp -run ^TestEmailNotification$

ok      github.com/group/project/pkg/employeeapp

now take a look at the synchronous Add() business function. Please see that Notify() call is synchronous.



// Add validates and save a new employee.
func (b *basicService) Add(ctx context.Context, newemployee Employee) (string, error) {
    newemployee.ID = uuid.New().String()
    // do some business logic
    b.notify(ctx, newemployee)
    return newemployee.ID, nil
}

// notify notifies to the employee using the given notifier.
func (b *basicService) notify(ctx context.Context, employee Employee) {
    if b.notifier == nil {
        return
    }
    newMessage := Message{
        Subject: "Hey",
        To:      employee.Email,
        From:    "anybody@somewhere.com",
        Body:    "Good morning there",
    }
    notifierErr := b.notifier.Notify(ctx, newMessage)
    if notifierErr != nil {
        log.Printf("unexpected error: %s sending message %+v to %q ", notifierErr, newMessage, employee.Email)
    }
}

We now receive a request from the tech leader requesting to call the Notify() function asynchronously.

Then we go to basicService logic and create a goroutine to call the internal notify function.



// Add validates and save a new employee.
func (b *basicService) Add(ctx context.Context, newemployee Employee) (string, error) {
    newemployee.ID = uuid.New().String()
    // do some business logic
    go b.notify(ctx, newemployee)
    return newemployee.ID, nil
}

Now we try to run our unit test, but wait, it does not work anymore.



go test -timeout 30s github.com/group/project/pkg/employeeapp -run ^TestEmailNotification$

--- FAIL: TestEmailNotification (0.00s)
panic: runtime error: index out of range [0] with length 0 [recovered]
    panic: runtime error: index out of range [0] with length 0

and it becomes worst when we add the -race flag.



go test -race -timeout 30s github.com/group/project/pkg/employeeapp -run ^TestEmailNotification$
--- FAIL: TestEmailNotification (0.00s)
==================
WARNING: DATA RACE
Write at 0x00c0000932d0 by goroutine 9:
  github.com/group/project/pkg/employeeapp_test.(*emailNotifierMock).Notify()

Well that's the reason of this article.

Solution

... One way to solve this could be to follow my proposal without changing our implementation.

Add a sync.WaitGroup and a sync.Mutex attributes in the Notifier mock.



// emailNotifierMock is a domain.Notifier mock that track
// received messages
type emailNotifierMock struct {
    err      error
    messages []employeeapp.Message
    mu       sync.Mutex
    wg       sync.WaitGroup
}

In the Notify() function within notifier mock we add a defer wg.Done() statement. Here we have to avoid race conditions on the messages slice, because we don't know how many goroutines could try to push items into it. That's the reason of the sync.Mutex attribute and the Lock() and Unlock() calls.



// Notify adds the given message to the messages map contained in the mock.
func (e *emailNotifierMock) Notify(ctx context.Context, message employeeapp.Message) error {
    defer e.wg.Done()
    if e.err != nil {
        return e.err
    }
    e.mu.Lock()
    e.messages = append(e.messages, message)
    e.mu.Unlock()
    return nil
}

In the unit test before calling the Add() function, we add the emailNotifier.wg.Add(1) statement and after calling the Add() function we add the following also emailNotifier.wg.Wait().



    ...
    // WHEN
    emailNotifier.wg.Add(1)
    _, err := basicService.Add(ctx, newEmployee)
    emailNotifier.wg.Wait()
    // THEN
    ...

obtaining this result.



import (
    "context"
    "sync"
    "testing"

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

func TestEmailNotification(t *testing.T) {
    // GIVEN
    newEmployee := employeeapp.Employee{
        FirstName: "Daenerys",
        LastName:  "Targaryen",
        Email:     "someone@somewhere.com",
        Salary:    25000,
    }
    expectedMessage := employeeapp.Message{
        Subject: "Hey",
        To:      "someone@somewhere.com",
        From:    "anybody@somewhere.com",
        Body:    "Good morning there",
    }
    ctx := context.TODO()
    emailNotifier := NewEmailNotifierMock()
    basicService := employeeapp.NewBasicService(emailNotifier)

    // WHEN
    emailNotifier.wg.Add(1)
    _, err := basicService.Add(ctx, newEmployee)
    emailNotifier.wg.Wait()
    // THEN
    if err != nil {
        t.Errorf("no error was expected but got: %q", err)
    }

    assert.Equal(t, expectedMessage, emailNotifier.messages[0])
}

now let's check the unit test again.



go test -race -timeout 30s github.com/group/project/pkg/employeeapp -run ^TestEmailNotification$

ok      github.com/group/project/pkg/employeeapp

Conclusion

Always make your code testeable. In the above scenario, the notifier has a well-known interface and even internally in the service, we are calling a private function.
The interfaces go a long way in making the code testable.
As much as possible, just test the public or visible features. Try not to make private functions part of your base code contract. That will give you flexibility in the future. Otherwise, feel free to test them with special care.
sync.WaitGroup library help us to wait for goroutines.
Mocks provide the opportunity to have control over the behavior of the code.
Remember to use go test -race if the unit test involves goroutines.

Acknowledgement

For modeling I was using PlantUML