[Golang (Go)] Use logrus package to output structured log

Posted on Edited on In , , , Views: Word count in article: 12k Reading time ≈ 11 mins.

logrus

Logrus is a structured logger for Go (golang), completely API compatible with the standard library logger.

Logrus is in maintenance-mode. We will not be introducing new features. It’s simply too hard to do in a way that won’t break many people’s projects, which is the last thing you want from your Logging library (again…).

This does not mean Logrus is dead. Logrus will continue to be maintained for security, (backwards compatible) bug fixes, and performance (where we are limited by the interface).

I believe Logrus’ biggest contribution is to have played a part in today’s widespread use of structured logging in Golang. There doesn’t seem to be a reason to do a major, breaking iteration into Logrus V2, since the fantastic Go community has built those independently. Many fantastic alternatives have sprung up. Logrus would look like those, had it been re-designed with what we know about structured logging in Go today. Check out, for example, Zerolog - https://github.com/rs/zerolog, Zap - https://github.com/uber-go/zap, and Apex - https://github.com/apex/log.

Installation

Standard go get:

1
$ go get -u github.com/sirupsen/logrus

Usage

With log.SetFormatter(&log.JSONFormatter{}), for easy parsing by logstash or Splunk:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
{"animal":"walrus","level":"info","msg":"A group of walrus emerges from the
ocean","size":10,"time":"2014-03-10 19:57:38.562264131 -0400 EDT"}

{"level":"warning","msg":"The group's number increased tremendously!",
"number":122,"omg":true,"time":"2014-03-10 19:57:38.562471297 -0400 EDT"}

{"animal":"walrus","level":"info","msg":"A giant walrus appears!",
"size":10,"time":"2014-03-10 19:57:38.562500591 -0400 EDT"}

{"animal":"walrus","level":"info","msg":"Tremendously sized cow enters the ocean.",
"size":9,"time":"2014-03-10 19:57:38.562527896 -0400 EDT"}

{"level":"fatal","msg":"The ice breaks!","number":100,"omg":true,
"time":"2014-03-10 19:57:38.562543128 -0400 EDT"}

With the default log.SetFormatter(&log.TextFormatter{}) when a TTY is not attached, the output is compatible with the logfmt format:

1
2
3
4
5
6
time="2015-03-26T01:27:38-04:00" level=debug msg="Started observing beach" animal=walrus number=8
time="2015-03-26T01:27:38-04:00" level=info msg="A group of walrus emerges from the ocean" animal=walrus size=10
time="2015-03-26T01:27:38-04:00" level=warning msg="The group's number increased tremendously!" number=122 omg=true
time="2015-03-26T01:27:38-04:00" level=debug msg="Temperature changes" temperature=-4
time="2015-03-26T01:27:38-04:00" level=panic msg="It's over 9000!" animal=orca size=9009
time="2015-03-26T01:27:38-04:00" level=fatal msg="The ice breaks!" err=&{0x2082280c0 map[animal:orca size:9009] 2015-03-26 01:27:38.441574009 -0400 EDT panic It's over 9000!} number=100 omg=true

To ensure this behaviour even if a TTY is attached, set your formatter as follows:

1
2
3
4
log.SetFormatter(&log.TextFormatter{
	DisableColors: true,
	FullTimestamp: true,
})

Logging Method Name

If you wish to add the calling method as a field, instruct the logger via:

1
log.SetReportCaller(true)

This adds the caller as ‘method’ like so:

1
2
3
{"animal":"penguin","level":"fatal","method":"github.com/sirupsen/arcticcreatures.migrate","msg":"a penguin swims by",
"time":"2014-03-10 19:57:38.562543129 -0400 EDT"}
time="2015-03-26T01:27:38-04:00" level=fatal method=github.com/sirupsen/arcticcreatures.migrate msg="a penguin swims by" animal=penguin

Note that this does add measurable overhead - the cost will depend on the version of Go, but is between 20 and 40% in recent tests with 1.6 and 1.7. You can validate this in your environment via benchmarks:

1
$ go test -bench=.*CallerTracing

Example

The simplest way to use Logrus is simply the package-level exported logger:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
package main

import (
  "os"
  log "github.com/sirupsen/logrus"
)

func init() {
  // Log as JSON instead of the default ASCII formatter.
  log.SetFormatter(&log.JSONFormatter{})

  // Output to stdout instead of the default stderr
  // Can be any io.Writer, see below for File example
  log.SetOutput(os.Stdout)

  // Only log the warning severity or above.
  log.SetLevel(log.WarnLevel)
}

func main() {
  log.WithFields(log.Fields{
    "animal": "walrus",
    "size":   10,
  }).Info("A group of walrus emerges from the ocean")

  log.WithFields(log.Fields{
    "omg":    true,
    "number": 122,
  }).Warn("The group's number increased tremendously!")

  log.WithFields(log.Fields{
    "omg":    true,
    "number": 100,
  }).Fatal("The ice breaks!")

  // A common pattern is to re-use fields between logging statements by re-using
  // the logrus.Entry returned from WithFields()
  contextLogger := log.WithFields(log.Fields{
    "common": "this is a common field",
    "other": "I also should be logged always",
  })

  contextLogger.Info("I'll be logged with common and other field")
  contextLogger.Info("Me too")
}

For more advanced usage such as logging to multiple locations from the same application, you can also create an instance of the logrus Logger:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
package main

import (
  "os"
  "github.com/sirupsen/logrus"
)

// Create a new instance of the logger. You can have any number of instances.
var log = logrus.New()

func main() {
  // The API for setting attributes is a little different than the package level
  // exported logger. See Godoc.
  log.Out = os.Stdout

  // You could set this to any `io.Writer` such as a file
  // file, err := os.OpenFile("logrus.log", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666)
  // if err == nil {
  //  log.Out = file
  // } else {
  //  log.Info("Failed to log to file, using default stderr")
  // }

  log.WithFields(logrus.Fields{
    "animal": "walrus",
    "size":   10,
  }).Info("A group of walrus emerges from the ocean")
}

Fields

Logrus encourages careful, structured logging through logging fields instead of long, unparseable error messages. For example, instead of: log.Fatalf(“Failed to send event %s to topic %s with key %d”), you should log the much more discoverable:

1
2
3
4
5
log.WithFields(log.Fields{
  "event": event,
  "topic": topic,
  "key": key,
}).Fatal("Failed to send event")

We’ve found this API forces you to think about logging in a way that produces much more useful logging messages. We’ve been in countless situations where just a single added field to a log statement that was already there would’ve saved us hours. The WithFields call is optional.

In general, with Logrus using any of the printf-family functions should be seen as a hint you should add a field, however, you can still use the printf-family functions with Logrus.

Default Fields

Often it’s helpful to have fields always attached to log statements in an application or parts of one. For example, you may want to always log the request_id and user_ip in the context of a request. Instead of writing log.WithFields(log.Fields{“request_id”: request_id, “user_ip”: user_ip}) on every line, you can create a logrus.Entry to pass around instead:

1
2
3
requestLogger := log.WithFields(log.Fields{"request_id": request_id, "user_ip": user_ip})
requestLogger.Info("something happened on that request") # will log request_id and user_ip
requestLogger.Warn("something not great happened")

Hooks

You can add hooks for logging levels. For example to send errors to an exception tracking service on Error, Fatal and Panic, info to StatsD or log to multiple places simultaneously, e.g. syslog.

Logrus comes with built-in hooks. Add those, or your custom hook, in init:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
import (
  log "github.com/sirupsen/logrus"
  "gopkg.in/gemnasium/logrus-airbrake-hook.v2" // the package is named "airbrake"
  logrus_syslog "github.com/sirupsen/logrus/hooks/syslog"
  "log/syslog"
)

func init() {

  // Use the Airbrake hook to report errors that have Error severity or above to
  // an exception tracker. You can create custom hooks, see the Hooks section.
  log.AddHook(airbrake.NewHook(123, "xyz", "production"))

  hook, err := logrus_syslog.NewSyslogHook("udp", "localhost:514", syslog.LOG_INFO, "")
  if err != nil {
    log.Error("Unable to connect to local syslog daemon")
  } else {
    log.AddHook(hook)
  }
}

A list of currently known service hooks can be found in this wiki page - https://github.com/sirupsen/logrus/wiki/Hooks.

Level logging

Logrus has seven logging levels: Trace, Debug, Info, Warning, Error, Fatal and Panic.

1
2
3
4
5
6
7
8
9
log.Trace("Something very low level.")
log.Debug("Useful debugging information.")
log.Info("Something noteworthy happened!")
log.Warn("You should probably take a look at this.")
log.Error("Something failed but I'm not quitting.")
// Calls os.Exit(1) after logging
log.Fatal("Bye.")
// Calls panic() after logging
log.Panic("I'm bailing.")

You can set the logging level on a Logger, then it will only log entries with that severity or anything above it:

1
2
// Will log anything that is info or above (warn, error, fatal, panic). Default.
log.SetLevel(log.InfoLevel)

It may be useful to set log.Level = logrus.DebugLevel in a debug or verbose environment if your application has that.

Entries

Besides the fields added with WithField or WithFields some fields are automatically added to all logging events:

  1. time. The timestamp when the entry was created.

  2. msg. The logging message passed to {Info,Warn,Error,Fatal,Panic} after the AddFields call. E.g. Failed to send event.

  3. level. The logging level. E.g. info.

Formatters

The built-in logging formatters are:

  • logrus.TextFormatter. Logs the event in colors if stdout is a tty, otherwise without colors.

    Note: to force colored output when there is no TTY, set the ForceColors field to true. To force no colored output even if there is a TTY set the DisableColors field to true. For Windows, see github.com/mattn/go-colorable.

    When colors are enabled, levels are truncated to 4 characters by default. To disable truncation set the DisableLevelTruncation field to true.

    When outputting to a TTY, it’s often helpful to visually scan down a column where all the levels are the same width. Setting the PadLevelText field to true enables this behavior, by adding padding to the level text.

All options are listed in the generated docs.

  • logrus.JSONFormatter. Logs fields as JSON.

See Formatters - https://github.com/sirupsen/logrus#formatters to learn more Formatters.

Rotation

Log rotation is not provided with Logrus. Log rotation should be done by an external program (like logrotate(8)) that can compress and delete old log entries. It should not be a feature of the application-level logger.

Tools

Tool Description
Logrus Mate - https://github.com/gogap/logrus_mate Logrus mate is a tool for Logrus to manage loggers, you can initial logger’s level, hook and formatter by config file, the logger will be generated with different configs in different environments.
Logrus Viper Helper - https://github.com/heirko/go-contrib/tree/master/logrusHelper An Helper around Logrus to wrap with spf13/Viper to load configuration with fangs! And to simplify Logrus configuration use some behavior of Logrus Mate - https://github.com/gogap/logrus_mate. sample - https://github.com/heirko/iris-contrib/blob/master/middleware/logrus-logger/example

Fatal handlers

Logrus can register one or more functions that will be called when any fatal level message is logged. The registered handlers will be executed before logrus performs an os.Exit(1). This behavior may be helpful if callers need to gracefully shutdown. Unlike a panic("Something went wrong...") call which can be intercepted with a deferred recover a call to os.Exit(1) can not be intercepted.

1
2
3
4
5
handler := func() {
  // gracefully shutdown something...
}

logrus.RegisterExitHandler(handler)

Thread safety

By default, Logger is protected by a mutex for concurrent writes. The mutex is held when calling hooks and writing logs. If you are sure such locking is not needed, you can call logger.SetNoLock() to disable the locking.

References

[1] sirupsen/logrus: Structured, pluggable logging for Go. - https://github.com/sirupsen/logrus