Logging an application in Go
Tags: go, log, clean, logger
Published: 2020-08-10 05:00:30

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

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

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

```go
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.

```shell
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.

```json
{"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](https://www.ardanlabs.com/blog/2017/05/design-philosophy-on-logging.html)

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

employee service
```go
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.

```go
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](https://github.com/sirupsen/logrus) library. Below you can check the `logrus` logger implementation.


```go
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.

```json
{"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](https://github.com/fernandoocampo/articles-code/tree/master/usefullog).

## 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](https://twitter.com/goinggodotnet) [philosophy](https://www.ardanlabs.com/blog/2017/05/design-philosophy-on-logging.html) about logging and errors.

## Acknowledgement

* For modeling I was using [PlantUML](https://plantuml.com)
* For testing assertions I use this library [Testify](https://github.com/stretchr/testify)
* Log levels reference with [log4j](https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/Level.html) in my old Java experience.

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