Logging an application in Go

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

Blog

Logging an application in Go

Fernando Ocampo

Context

Problem

Solution

Conclusion

Acknowledgement

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

Related