"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.
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
debugto track the flow of the application and show fine-grained data in favor of debugging. - With the
infolevel I log what may be of interest to administrators and show the progress of the application. - Level of
erroronly 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.
Top comments (0)