Having good logging is crucial for running and debugging applications in production. It reduces your issue to resolution time by providing details about every action, request, and response. Designing a good logging system isn’t a trivial task, and requires an eye for detail. Here’s how I do it in Go!
No matter the language you used, you were probably logging things to ease your debugging. Printing to stdout works on your local machine, but as soon as you have to deploy it becomes harder to deal with, especially if you need to scale and run your application across multiple servers.
That’s where external tools come into place, such as Kibana (ELK stack), Greylog, Datadog … What these have in common is that they require logging to be in a common format, most often JSON. This requires using structured loggers, that output your log lines as JSON (or other structured formats).
Choosing a library
Go has many libraries built around this purpose, with popular ones such as Logrus, Zap and Zerolog. Most of them are similar to each other in terms of their functionality. I’ve been using Zerolog for quite some time and this blog post is using zerolog (you can apply most of the guide for other libraries), but I wouldn’t recommend you using it. Why?
There is a disclaimer at the bottom of Zerolog’s readme stating:
Note that zerolog does no de-duplication of fields. Using the same key multiple times creates multiple keys in the final JSON: In this case, many consumers will take the last value, but this is not guaranteed; check yours if in doubt.
I had this exact issue more than once where logs were missing from the log dashboard as the agent couldn’t pick up log lines with invalid JSON.
Zerolog author claims better performance over other libraries, but I’m unsure how logging affects service performance, unless it’s something highly performance-critical.
Logging to file instead of stdout
Besides structured logging, some agents are parsing logs from a file. I’m using lumberjack to achieve this in Go.
z := zerolog.New(&lumberjack.Logger{
Filename: "file.log", // File name
MaxSize: 100, // Size in MB before file gets rotated
MaxBackups: 5, // Max number of files kept before being overwritten
MaxAge: 30, // Max number of days to keep the files
Compress: true, // Whether to compress log files using gzip
})Initializing logger
The actual first step you need to do is initialize the logger:
z := zerolog.New(&lumberjack.Logger{
Filename: cfg.Filename,
MaxSize: cfg.MaxSize, // m
MaxBackups: cfg.MaxBackups,
MaxAge: cfg.MaxAge,
Compress: cfg.Compress,
})
return z.With().Caller().Timestamp().Logger()With this, your zerolog instance is initiated and you can start logging. What I sometimes do is create a global instance of the logger, in case I want to handle an error by logging it and continuing with execution.
// Logger is global logger
var Logger zerolog.Logger
z := zerolog.New(&lumberjack.Logger{
Filename: cfg.Filename,
MaxSize: cfg.MaxSize, // m
MaxBackups: cfg.MaxBackups,
MaxAge: cfg.MaxAge,
Compress: cfg.Compress,
})
z = z.With().Caller().Timestamp().Logger()
Logger = z
return zLogging middleware
With our logging instance ready it’s time to start logging http requests. Go has excellent middleware support, and our primary logging mechanism will be one.
We’ll be logging requests, responses, status codes, and many more there. With logging, there is a philosophy where logs are recorded only for errors/warnings, and for success cases, you rely purely on metrics. Whether or not you support this, it’s easy to update the middleware to ignore/exclude logs where the status is <500.
func Logger(l zerolog.Logger) mux.MiddlewareFunc {
return func(next http.Handler) http.Handler {
// Logs all responses.
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
ww := NewWrapResponseWriter(w, r.ProtoMajor)
rec := httptest.NewRecorder()
ctx := r.Context()
path := r.URL.EscapedPath()
reqData, _ := httputil.DumpRequest(r, false)
logger := l.Log().Timestamp().Str("path", path).Bytes("request_data", reqData)
defer func(begin time.Time) {
status := ww.Status()
tookMs := time.Since(begin).Milliseconds()
logger.Int64("took", tookMs).Int("status_code", status).Msgf("[%d] %s http request for %s took %dms", status, r.Method, path, tookMs)
}(time.Now())
// Replace "logger" with a custom type, like ContextKey("logger")
ctx = context.WithValue(ctx, "logger", logger)
next.ServeHTTP(rec, r.WithContext(ctx))
// this copies the recorded response to the response writer
for k, v := range rec.Header() {
ww.Header()[k] = v
}
ww.WriteHeader(rec.Code)
rec.Body.WriteTo(ww)
})
}
}This is a basic HTTP middleware logger. It logs the path, request_data, status, and latency. It also adds the logger in the context, so it can be used down the line. The NewWrapResponseWriter code can be found on Gist, which allows you to hook into ResponseWriter and get the actual status/headers.
You usually have an authentication middleware, that parses session cookies/token/JWT and authorizes requests. In that middleware, I log userID, username, cookie/token, and possibly user object.
// Authnr middleware
token := r.Header.Get("Authorization")
user := getUserFromToken(token)
// Do actual authorization
ctx := r.Context()
logger := context.Value(r.Context(), "logger").(*zerolog.Event)
logger.Str("user_id", user.ID).Str("user_name", user.Username).Str("token", token)
r = r.WithContext(context.WithValue(ctx, "logger", logger))As you’ll be passing context around your code, you can easily pull out the logger and log specific fields you may need. I have a helper function that pulls logger from context, and if it’s not present, create a new instance of logger.
func FromContext(ctc context.Context) *zerolog.Event{
logger, ok := ctx.Value(ContextKey("logger")).(*zerolog.Event)
if ok {
return logger
}
return Logger.Log().Timestamp()
}Recover middleware
If you have a recover middleware, which you should, you can log the stacktrace, actual error and panic details like:
// Recover any panics from upstream.
func Recover(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
defer func() {
if err := recover(); err != nil {
ctx := r.Context()
logger := zlog.FromContext(ctx)
stack := make([]byte, 8096)
stack = stack[:runtime.Stack(stack, false)]
logger.Bytes("stack", stack).Str("level", "fatal").Interface("error", err)
hasRecovered, ok := ctx.Value(polymer.ContextKey("has_recovered")).(*bool)
if ok {
*hasRecovered = true
}
http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
}
}()
next.ServeHTTP(w, r)
})
}I use the hasRecovered value in context to prevent ZeroLog from logging level field twice, and instead, log it with fatal level. If you log panics with error level you don’t need to do this.
I’ve written about how to do this in Pushing data upstream in context.
Hooks and constant logging context
There are certain things you’d like to include in every logline. Stuff like sha1 of the commit, build date/number, start date.
With Go’s X flags, it’s quite easy to pass sha1 to the Go executable. Once you have it, adding it to logger is even easier:
type TraceDisableHook struct {
nonLocal bool
}
// Run implements hook interface
func (t TraceDisableHook) Run(e *zerolog.Event, lvl zerolog.Level, _ string) {
if t.nonLocal && lvl == zerolog.TraceLevel {
e.Discard()
}
}
func New(apiVersion string, nonLocal bool, cfg Config) zerolog.Logger {
traceDisableHook := TraceDisableHook{nonLocal: nonLocal}
return zerolog.New(os.Stdout).With().Timestamp().
Str("api_version", apiVersion).
Str("github_link", fmt.Sprintf("https://github.com/organization/project/tree/%s", apiVersion)).
Caller().Logger().Hook(traceDisableHook)Commit number and build/start date are static values determined during build/server startup. But some values are dynamic and the logger cannot be instantiated with them. Hooks are a way to dynamically add data to logs, supported by most major logging libraries.
In the above example, the TraceDisableHook disables all trace level logs for non-local environments (there’s a better way to do this with ZeroLog). Hooks offer a great way to easily extend your logs with the context you need.