Softwares break. And when it does finding the problem, fixing it in a very limited time becomes of utmost importance. Proper logging can help you localize the problem and give you context on what broke. In this post we will learn how to use different logging techniques provided by go ecosystem. And how to build your program independent of which logging library you choose.

Hold the door

One of the most important software engineering philosophy is to not let the 3rd party code slip into the scope of your domain code. There are many ways logging can be achieved and we want that our domain code does not change when we decide to change our logging library. In order to do that we would first need to identify what are the capabilities we need from our Logger. It must provide different levels of logging, debug, info, error, fatal etc. It must provide the flexibility to choose the standard output to which we wish to write our log to(stdout or file, or both). Should support structured logging, JSON formatting for logs etc. Below is the code for creating the Logger interface among other stuff.

File logger.go

package logger

import "errors"

// A global variable so that log functions can be directly accessed
var log Logger

//Fields Type to pass when we want to call WithFields for structured logging
type Fields map[string]interface{}

const (
	//Debug has verbose message
	Debug = "debug"
	//Info is default log level
	Info = "info"
	//Warn is for logging messages about possible issues
	Warn = "warn"
	//Error is for logging errors
	Error = "error"
	//Fatal is for logging fatal messages. The sytem shutsdown after logging the message.
	Fatal = "fatal"
)

const (
	InstanceZapLogger int = iota
	InstanceLogrusLogger
)

var (
	errInvalidLoggerInstance = errors.New("Invalid logger instance")
)

//Logger is our contract for the logger
type Logger interface {
	Debugf(format string, args ...interface{})

	Infof(format string, args ...interface{})

	Warnf(format string, args ...interface{})

	Errorf(format string, args ...interface{})

	Fatalf(format string, args ...interface{})

	Panicf(format string, args ...interface{})

	WithFields(keyValues Fields) Logger
}

// Configuration stores the config for the logger
// For some loggers there can only be one level across writers, for such the level of Console is picked by default
type Configuration struct {
	EnableConsole     bool
	ConsoleJSONFormat bool
	ConsoleLevel      string
	EnableFile        bool
	FileJSONFormat    bool
	FileLevel         string
	FileLocation      string
}

//NewLogger returns an instance of logger
func NewLogger(config Configuration, loggerInstance int) error {
	switch loggerInstance {
	case InstanceZapLogger:
		logger, err := newZapLogger(config)
		if err != nil {
			return err
		}
		log = logger
		return nil

	case InstanceLogrusLogger:
		logger, err := newLogrusLogger(config)
		if err != nil {
			return err
		}
		log = logger
		return nil

	default:
		return errInvalidLoggerInstance
	}
}

func Debugf(format string, args ...interface{}) {
	log.Debugf(format, args...)
}

func Infof(format string, args ...interface{}) {
	log.Infof(format, args...)
}

func Warnf(format string, args ...interface{}) {
	log.Warnf(format, args...)
}

func Errorf(format string, args ...interface{}) {
	log.Errorf(format, args...)
}

func Fatalf(format string, args ...interface{}) {
	log.Fatalf(format, args...)
}

func Panicf(format string, args ...interface{}) {
	log.Panicf(format, args...)
}

func WithFields(keyValues Fields) Logger {
	return log.WithFields(keyValues)
}

Now all we have to do is implement the Logger interface according to any of the logging libraries and our domain does not change. Let’s implement the Logger interface for zap and logrus.

Zap implementation

Zap is a logging library provided by uber. It’s main focus is performance and the benchmarks shows really impressive number. Zap has two flavors of loggers SugaredLogger and Logger.

  • SugaredLogger

SugaredLogger provides both structured logging and printf style APIs. The structured logging provided by it is more flexible and does not make your code tightly coupled to zap. SugaredLogger is less performant than zap’s Logger but the difference is very minute. Example from the documentation:

  logger, _ := zap.NewProduction()
  defer logger.Sync() // flushes buffer, if any
  sugar := logger.Sugar()
  sugar.Infow("failed to fetch URL",
  // Structured context as loosely typed key-value pairs.
  "url", "http://example.com",
  "attempt", 3,
  "backoff", time.Second,
  )
  //SugaredLogger also supports only printf like logging
  sugar.Infof("Failed to fetch URL: %s", "http://example.com")

  • Logger

Logger only provides structured logging and is more performant than sugger logging. It is a type-safe way of logging structured fields. Example from documentation:

  logger, _ := zap.NewProduction()
  defer logger.Sync()
  logger.Info("failed to fetch URL",
  // Structured context as strongly typed Field values.
  zap.String("url", url),
  zap.Int("attempt", 3),
  zap.Duration("backoff", time.Second),
  )

This makes using Logger a bit harder as changing library is no more simple. Therefore we go with the SugaredLoger approach.

Since we will be supporting both console and file based logging(if the configuration is set by user), we won’t directly use zap.NewProduction(), which provides sane defaults. Also for file logging we will use another library called as Lumberjack which provides rolling log files. Below is the zap implementation of our logger.

File zap.go

package logger

import (
	"os"

	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
	lumberjack "gopkg.in/natefinch/lumberjack.v2"
)

type zapLogger struct {
	sugaredLogger *zap.SugaredLogger
}

func getEncoder(isJSON bool) zapcore.Encoder {
	encoderConfig := zap.NewProductionEncoderConfig()
	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
	if isJSON {
		return zapcore.NewJSONEncoder(encoderConfig)
	}
	return zapcore.NewConsoleEncoder(encoderConfig)
}

func getZapLevel(level string) zapcore.Level {
	switch level {
	case Info:
		return zapcore.InfoLevel
	case Warn:
		return zapcore.WarnLevel
	case Debug:
		return zapcore.DebugLevel
	case Error:
		return zapcore.ErrorLevel
	case Fatal:
		return zapcore.FatalLevel
	default:
		return zapcore.InfoLevel
	}
}

func newZapLogger(config Configuration) (Logger, error) {
	cores := []zapcore.Core{}

	if config.EnableConsole {
		level := getZapLevel(config.ConsoleLevel)
		writer := zapcore.Lock(os.Stdout)
		core := zapcore.NewCore(getEncoder(config.ConsoleJSONFormat), writer, level)
		cores = append(cores, core)
	}

	if config.EnableFile {
		level := getZapLevel(config.FileLevel)
		writer := zapcore.AddSync(&lumberjack.Logger{
			Filename: config.FileLocation,
			MaxSize:  100,
			Compress: true,
			MaxAge:   28,
		})
		core := zapcore.NewCore(getEncoder(config.FileJSONFormat), writer, level)
		cores = append(cores, core)
	}

	combinedCore := zapcore.NewTee(cores...)

  // AddCallerSkip skips 2 number of callers, this is important else the file that gets 
  // logged will always be the wrapped file. In our case zap.go
	logger := zap.New(combinedCore,
		zap.AddCallerSkip(2),
		zap.AddCaller(),
	).Sugar()

	return &zapLogger{
		sugaredLogger: logger,
	}, nil
}

func (l *zapLogger) Debugf(format string, args ...interface{}) {
	l.sugaredLogger.Debugf(format, args...)
}

func (l *zapLogger) Infof(format string, args ...interface{}) {
	l.sugaredLogger.Infof(format, args...)
}

func (l *zapLogger) Warnf(format string, args ...interface{}) {
	l.sugaredLogger.Warnf(format, args...)
}

func (l *zapLogger) Errorf(format string, args ...interface{}) {
	l.sugaredLogger.Errorf(format, args...)
}

func (l *zapLogger) Fatalf(format string, args ...interface{}) {
	l.sugaredLogger.Fatalf(format, args...)
}

func (l *zapLogger) Panicf(format string, args ...interface{}) {
	l.sugaredLogger.Fatalf(format, args...)
}

func (l *zapLogger) WithFields(fields Fields) Logger {
	var f = make([]interface{}, 0)
	for k, v := range fields {
		f = append(f, k)
		f = append(f, v)
	}
	newLogger := l.sugaredLogger.With(f...)
	return &zapLogger{newLogger}
}

And that’s zap implementation of our Logger interface. Let’s go ahead and implement the same for logrus.

Logrus Implementation

Logrus implementation is more or less the same with the zap implementation with one difference being how we implement the WithFields method. Logrus creates a new type called logrus.Entry when we try to call a WithFields on Logrus.Logger. Therefore we need to have our own struct wrap over Entry and have the logger implementation for it as well. Below is the code:

File logrus.go

package logger

import (
	"io"
	"os"

	"github.com/sirupsen/logrus"
	lumberjack "gopkg.in/natefinch/lumberjack.v2"
)

type logrusLogEntry struct {
	entry *logrus.Entry
}

type logrusLogger struct {
	logger *logrus.Logger
}

func getFormatter(isJSON bool) logrus.Formatter {
	if isJSON {
		return &logrus.JSONFormatter{}
	}
	return &logrus.TextFormatter{
		FullTimestamp:          true,
		DisableLevelTruncation: true,
	}
}

func newLogrusLogger(config Configuration) (Logger, error) {
	logLevel := config.ConsoleLevel
	if logLevel == "" {
		logLevel = config.FileLevel
	}

	level, err := logrus.ParseLevel(logLevel)
	if err != nil {
		return nil, err
	}

	stdOutHandler := os.Stdout
	fileHandler := &lumberjack.Logger{
		Filename: config.FileLocation,
		MaxSize:  100,
		Compress: true,
		MaxAge:   28,
	}
	lLogger := &logrus.Logger{
		Out:       stdOutHandler,
		Formatter: getFormatter(config.ConsoleJSONFormat),
		Hooks:     make(logrus.LevelHooks),
		Level:     level,
	}

	if config.EnableConsole && config.EnableFile {
		lLogger.SetOutput(io.MultiWriter(stdOutHandler, fileHandler))
	} else {
		if config.EnableFile {
			lLogger.SetOutput(fileHandler)
			lLogger.SetFormatter(getFormatter(config.FileJSONFormat))
		}
	}

	return &logrusLogger{
		logger: lLogger,
	}, nil
}

func (l *logrusLogger) Debugf(format string, args ...interface{}) {
	l.logger.Debugf(format, args...)
}

func (l *logrusLogger) Infof(format string, args ...interface{}) {
	l.logger.Infof(format, args...)
}

func (l *logrusLogger) Warnf(format string, args ...interface{}) {
	l.logger.Warnf(format, args...)
}

func (l *logrusLogger) Errorf(format string, args ...interface{}) {
	l.logger.Errorf(format, args...)
}

func (l *logrusLogger) Fatalf(format string, args ...interface{}) {
	l.logger.Fatalf(format, args...)
}

func (l *logrusLogger) Panicf(format string, args ...interface{}) {
	l.logger.Fatalf(format, args...)
}

func (l *logrusLogger) WithFields(fields Fields) Logger {
	return &logrusLogEntry{
		entry: l.logger.WithFields(convertToLogrusFields(fields)),
	}
}

func (l *logrusLogEntry) Debugf(format string, args ...interface{}) {
	l.entry.Debugf(format, args...)
}

func (l *logrusLogEntry) Infof(format string, args ...interface{}) {
	l.entry.Infof(format, args...)
}

func (l *logrusLogEntry) Warnf(format string, args ...interface{}) {
	l.entry.Warnf(format, args...)
}

func (l *logrusLogEntry) Errorf(format string, args ...interface{}) {
	l.entry.Errorf(format, args...)
}

func (l *logrusLogEntry) Fatalf(format string, args ...interface{}) {
	l.entry.Fatalf(format, args...)
}

func (l *logrusLogEntry) Panicf(format string, args ...interface{}) {
	l.entry.Fatalf(format, args...)
}

func (l *logrusLogEntry) WithFields(fields Fields) Logger {
	return &logrusLogEntry{
		entry: l.entry.WithFields(convertToLogrusFields(fields)),
	}
}

func convertToLogrusFields(fields Fields) logrus.Fields {
	logrusFields := logrus.Fields{}
	for index, val := range fields {
		logrusFields[index] = val
	}
	return logrusFields
}

Change is the only constant

Since we have abstracted the actual logging library behind our own Logger interface we can easily change among the given two implementations. Why would a change be required though? Well we don’t know, there could be many reasons, but now we have a construct in which incorporating the changes is easy. Below is the code to demonstrate this:

package main

import (
	"log"
	"os"

	"github.com/amitrai48/logger"
)

func main() {
	config := logger.Configuration{
		EnableConsole:     true,
		ConsoleLevel:      logger.Debug,
		ConsoleJSONFormat: true,
		EnableFile:        true,
		FileLevel:         logger.Info,
		FileJSONFormat:    true,
		FileLocation:      "log.log",
	}
	err := logger.NewLogger(config, logger.InstanceZapLogger)
	if err != nil {
		log.Fatalf("Could not instantiate log %s", err.Error())
	}
	
  contextLogger := logger.WithFields(logger.Fields{"key1": "value1"})
  contextLogger.Debugf("Starting with zap")
  contextLogger.Infof("Zap is awesome")
  
  err = logger.NewLogger(config, logger.InstanceLogrusLogger)
    if err != nil {
      log.Fatalf("Could not instantiate log %s", err.Error())
    }
  contextLogger = logger.WithFields(logger.Fields{"key1": "value1"})
  contextLogger.Debugf("Starting with logrus")
  
  contextLogger.Infof("Logrus is awesome")
}

And here is the output of the above program:

{"level":"debug","ts":"2019-01-26T20:10:51.176+0530","caller":"runtime/proc.go:201",
"msg":"Starting with zap","key1":"value1"}

{"level":"info","ts":"2019-01-26T20:10:51.176+0530","caller":"runtime/proc.go:201",
"msg":"Zap is awesome","key1":"value1"}

{"key1":"value1","level":"debug","msg":"Starting with logrus","time":"2019-01-26T20:10:51+05:30"}

{"key1":"value1","level":"info","msg":"Logrus is awesome","time":"2019-01-26T20:10:51+05:30"}

Sidenote - the caller key prints runtime/proc.go instead of the actual file where the log is called, it happens when WithFields is called for zap. I haven’t been able to figure out how to fix this.

Output Format? I did not think of that

While you are able to change the logger without an issue, the outputs by different implementation could be different. This would defeat the purpose of abstracting the logger implementation. Imagine you have a pipeline which receives the logs as input and performs some action on it.

And when you change your logger this output changes and your pipeline might start breaking. Luckily most of the logging libraries are very flexible with their formatters. You can change the formatter to your custom model and make sure every logger implementation follows it.

For our example scenario one major difference in the outputs is the time key. While in the zap implementation it is shown as ts, the logrus implementation prints it as time. Lets change the zap implementation to display the TimeKey as time. Add the following line in zap.go file:

File zap.go

func getEncoder(isJSON bool) zapcore.Encoder {
encoderConfig := zap.NewProductionEncoderConfig()
encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
encoderConfig.TimeKey = "time" // This will change the key from ts to time
//Rest of the code remains same

This was just to show you the importance of having a common output from your different logging libraries. I would encourage you to build a custom formatter and have your logger implementation stick to it.

Conclusion

Take this learning from the logs and apply it to any third party library you are planning to use. Always hold the door against third party libraries creeping into the scope of your code.