For our Pipeline Platform, observability is an essential part of operating distributed applications in production. We put a great deal of effort into monitoring large and federated clusters, and automating the centralized log collection of these clusters with Pipeline. That way, all our users get out-of-the-box observability for free .

So far, we’ve concentrated on high level and infrastructural aspects of logging. In this blog post we’ll be examining the practice at a more fundemental level, the application level , as we explore the logging library itself.

While working on Pipeline we needed function, package and line number information about our log messages. We use Logrus, but we could not find an adequate extension, so we open-sourced a Logrus runtime Formatter, which automatically tags log messages with runtime/stack information without code modification.

During logging events inside applications, it’s crucial to know where the event has happened in the execution flow, which function logged the event, which line, and in which package. This information helps a lot during a debugging session. Additionaly, this information may provide insights when applying data science to log archives when extracting, for example, the most frequently used execution paths in an application. Maintaining log messages is manual, repetitive work. Most developers don’t like to, or simply forget to, maintain them; also, there is a change factor which saddles logs messages (just like code comments) with an expiration date. At Banzai Cloud we like to automate as much as possible, whenever feasible, so we automated maintaining our log messages as well.

Logging the Logrus way 🔗︎

Logrus is a great library for logging in Go. We like it and have used it in almost every application and library we’ve written up to this point. It’s a very pluggable, easy to use library, with a lot of extensions on top of it; it’s modular capabilities, like custom Formatters and Hooks make it the de-facto logging library for Golang (at least in our opinion).

1 package main 2 3 import ( 4 "os" 5 log "github.com/sirupsen/logrus" 6 ) 7 8 func init () { 9 // Log as JSON instead of the default ASCII formatter. 10 log . SetFormatter ( & log . JSONFormatter {}) 11 12 // Output to stdout instead of the default stderr 13 // Can be any io.Writer, see below for File example 14 log . SetOutput ( os . Stdout ) 15 16 // Only log the info severity or above. 17 log . SetLevel ( log . InfoLevel ) 18 } 19 20 func foo () { 21 log . WithFields ( log . Fields { 22 "prefix" : "sensor" , 23 "temperature" : - 4 , 24 }). Info ( "Temperature changes" ) 25 } 26 27 func main () { 28 foo () 29 }

The output of running this example with go run :

1 { "level" : "info" , "msg" : "Temperature changes" , "prefix" : "sensor" , "temperature" : -4 , "time" : "2018-06-04T07:26:34+02:00" }

Using the runtime based Formatter with Logrus 🔗︎

At Banzai Cloud a lot of us have a background in Java. We missed what we thought should be a key feature in Logrus - automatic tagging of log messages with runtime/stack information. This feature is already available in popular Java logging libraries like Logback. We conducted an exhaustive search, but found no library for Logrus with that feature, so we decided to write our own Formatter, which would do that work for us. Here’s how to use it with Logrus:

1 package main 2 3 import ( 4 "os" 5 log "github.com/sirupsen/logrus" 6 runtime "github.com/banzaicloud/logrus-runtime-formatter" 7 ) 8 9 func init () { 10 // Log as JSON instead of the default ASCII formatter, but wrapped with the runtime Formatter. 11 formatter := runtime . Formatter { ChildFormatter : & log . JSONFormatter {}} 12 // Enable line number logging as well 13 formatter . Line = true 14 15 // Replace the default Logrus Formatter with our runtime Formatter 16 log . SetFormatter ( & formatter ) 17 18 // Output to stdout instead of the default stderr 19 // Can be any io.Writer, see below for File example 20 log . SetOutput ( os . Stdout ) 21 22 // Only log the info severity or above. 23 log . SetLevel ( log . InfoLevel ) 24 } 25 26 func foo () { 27 log . WithFields ( log . Fields { 28 "prefix" : "sensor" , 29 "temperature" : - 4 , 30 }). Info ( "Temperature changes" ) 31 } 32 33 func main () { 34 foo () 35 }

The output of running this example with go run :

1 { "function" : "foo" , "level" : "info" , "line" : "30" , "msg" : "Temperature changes" , "prefix" : "sensor" , "temperature" : -4 , "time" : "2018-06-04T07:27:12+02:00" }

How it works 🔗︎

The workhorse of this small library is the runtime.Caller(skip int) function. This does the work of determining the currently executed function by analyzing the call stack of the current goroutine. The skip parameter specifies how many frames the function should skip back on the current call stack. This is needed for getting, for example, the function logrus.Infoln(...) , because Formatters are executed inside the Logrus call stack, so would require that we skip back to the actual application code. It uses a heuristic technique to determine function correctly. To do this we had to analyze the Logrus library carefully, to determine how many functions we need to skip to get to the correct one. The library, itself, has been challenged with test cases to make sure we test every execution scenario we’ve faced until now.

We’ve tested the library in our main application, Pipeline, and haven’t observed any kind of measurable overhead; this is probably because the application uses a lot of IO intensive operations (which most applications do!).

The test suite includes a benchmark, which compares the execution times with the base Logrus Formatters:

go test -bench = . -benchmem goos: darwin goarch: amd64 pkg: github.com/banzaicloud/logrus-runtime-formatter BenchmarkErrorRuntimeAndTextFormatter-4 500000 3191 ns/op 26.00 MB/s 822 B/op 15 allocs/op BenchmarkErrorTextFormatter-4 1000000 1556 ns/op 43.06 MB/s 454 B/op 12 allocs/op BenchmarkSmallRuntimeAndTextFormatter-4 500000 3110 ns/op 32.79 MB/s 848 B/op 13 allocs/op BenchmarkSmallTextFormatter-4 1000000 1435 ns/op 59.90 MB/s 480 B/op 10 allocs/op BenchmarkLargeRuntimeAndTextFormatter-4 100000 11617 ns/op 26.00 MB/s 6445 B/op 19 allocs/op BenchmarkLargeTextFormatter-4 300000 4984 ns/op 57.38 MB/s 1728 B/op 12 allocs/op BenchmarkSmallRuntimeAndJSONFormatter-4 200000 5884 ns/op 22.77 MB/s 2368 B/op 34 allocs/op BenchmarkSmallJSONFormatter-4 500000 3732 ns/op 30.54 MB/s 1648 B/op 28 allocs/op BenchmarkLargeRuntimeAndJSONFormatter-4 100000 22673 ns/op 18.96 MB/s 11629 B/op 87 allocs/op BenchmarkLargeJSONFormatter-4 100000 16407 ns/op 24.99 MB/s 6906 B/op 78 allocs/op PASS ok github.com/banzaicloud/logrus-runtime-formatter 17.501s ------------------------------------------------------------

As you can see, execution differs most when compared to the logrus.TextFormatter , but when compared to the logrus.JSONFormatter the difference shrinks considerably. We are actively working on making these differences even smaller.

To summarize, you can get function, package and line number information with almost no code changes to your Golang application as long as you’re already using Logrus.

You can find the project on our GitHub repository at logrus-runtime-formatter.