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.
Logging series:
Centralized logging under Kubernetes
Secure logging on Kubernetes with Fluentd and Fluent Bit
Advanced logging on Kubernetes
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.
tl;dr: 🔗︎
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.
Logging 🔗︎
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).
1package main
2
3import (
4 "os"
5 log "github.com/sirupsen/logrus"
6)
7
8func 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
20func foo() {
21 log.WithFields(log.Fields{
22 "prefix": "sensor",
23 "temperature": -4,
24 }).Info("Temperature changes")
25}
26
27func 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:
1package main
2
3import (
4 "os"
5 log "github.com/sirupsen/logrus"
6 runtime "github.com/banzaicloud/logrus-runtime-formatter"
7)
8
9func 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
26func foo() {
27 log.WithFields(log.Fields{
28 "prefix": "sensor",
29 "temperature": -4,
30 }).Info("Temperature changes")
31}
32
33func 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.
Benchmarks 🔗︎
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.
Conclusion 🔗︎
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.
