Seite wählen

The Walrus Has Landed – Structured Logging in Go

von | Aug 2, 2018 | Golang

Walrus pup at Kamogawa Seaworld, Japan. Photo by Max Smith.

Logs let us understand which combination over time lead to a specific event, we can further analyze them to monitor trends or have them print enough information to narrow down a problem to a single line of code. They are the written history of the IT world. Did I lay it on too thick? Probably. But the bottom line is, logs can be very useful. But before you can read logs, one has to write log messages, assign severities and decide which information is worth print and which is not.
An attempt to make logging easier for the programmer, more readable for the user and better formatted for log processors is structured logging. This concept has been around for a while but ‚got cool‘ only recently with the advent of large scale logging processors like ElasticSearch or Graylog. Let’s go by example, the following are two log messages, the first being good old lines of text and the second structured logging

[2018-07-31T16:25:07+02:00] - Information/Api: New connection ("GET") from "" to endpoint "/v1/get-the-cookie" with token "aa76dfdf1023dfa567".
time="2018-07-31T16:25:07+02:00" level=Info msg="New connection" context=Api request_type=GET remote= endpoint=/v1/get-the-cookie authtoken="aa76dfdf1023dfa567

It’s easy to see how the structured logging message is easier to comprehend for a logging processor. And while you can grep use grep on both the same way to get a quick overview in this case, the key=’value‘ scheme of the second line will always have that advantage while string logs may get convoluted – we all had to chain multiple instances of `grep` and `grep -i` to get rid of false positives at some point, no?
Now let’s look at the code, since I promised it would be easier for developers as well. In this case I’ll be using logrus, a structured logging library for Go. Here is code how these two lines could look like:

log.Information("Api", "New connection (\"%s\") from \"%s\" to endpoint \"%s\" with token \"%s\", conn.type, conn.remote, conn.path, conn.token)

Simple enough. Timestamps are automatic, the severity part of the function call and the context is one of the parameters. Now the same with logrus:

		"context":      "Api",
		"request_type": conn.type,
		"remote":       conn.remote,
		"endpoint":     conn.path,
		"authtoken":    conn.token
	}).Info("New connection")

This looks like a lot more to write and less simple at that! Was I lying? Of course not. The big advantage of using logrus are temporary loggers with default fields:

apiLogger := log.WithFields(log.Fields{
		"context":      "Api",
		"request_type": conn.type,
		"remote":       conn.remote,
		"endpoint":     conn.path,
		"authtoken":    conn.token
apiLogger.Info("New connection")

Any future logging within the Api context can use this `apiLogger`. Letting us shape the log messages with exactly the information we need, without too much copy and paste or having to think about the type of object we want to log:

apiLogger.WithField("data",conn.data).Debug("Submitted Data")
		"error": "Too much data",
		"error_id": 5,
	}).Warn("Connectivity issue")
apiLogger.Info("Connection terminated")
.... Outputs:
time="2018-07-31T16:25:17+02:00" level=Info msg="New connection" context=Api request_type=POST remote= endpoint=/v1/give-me-cookies authtoken=aa76dfdf1023dfa567
time="2018-07-31T16:25:09+02:00" level=Debug msg="Submitted Data" context=Api request_type=POST remote= endpoint=/v1/give-me-cookies authtoken=aa76dfdf1023dfa567 submitted_data="{some json blob}"
time="2018-07-31T16:25:17+02:00" level=Warn msg="Connectivity issue" context=Api request_type=POST remote= endpoint=/v1/give-me-cookies authtoken=aa76dfdf1023dfa567 error="Too much data" error_id=5
time="2018-07-31T16:25:24+02:00" level=Info msg="Connection terminated" context=Api request_type=POST remote= endpoint=/v1/give-me-cookies authtoken=aa76dfdf1023dfa567

It’s easy to see how having to write log messages the usual way would be quite tiresome and prone to missing some information, be it by oversight or misjudged importance. Stay tuned for future updates on our journey into the world of Golang and hopefully we’ll see you at OSMC.

Mehr Beiträge zum Thema Golang

NETWAYS Support Collector Roadmap

Den Support Collector konnte ich bereits in meinem letzten Blogpost vorstellen. Für alle die den Beitrag verpasst haben, hier kurz umrissen was es ist: Bei dem Tool handelt es sich um einen von uns geschriebenen Datensammler, welche alle möglichen Support relevanten...

Der NETWAYS Support Collector

Dem ein oder anderen unserer Support Kunden ist unser neuer Support Collector vielleicht schon über den Weg gelaufen. Aber was ist das überhaupt? Und was bringt er? Der NETWAYS Support Collector ist eines unserer neuesten Kreationen. Inspiriert von, dem mehr...

Icinga Plugins in Golang

Golang ist an sich noch eine relativ junge Programmiersprache, ist jedoch bei vielen Entwicklern und Firmen gut angekommen und ist die Basis von vielen modernen Software Tools, von Docker bis Kubernetes. Für die Entwicklung von Icinga Plugins bringt die Sprache einige...

C++Go. Halb C++ – halb Go.

Scherz beiseite, die Go-Entwickler bieten noch keine Möglichkeit, C++-Bibliotheken ohne weiteres anzusprechen. Aber es geht ja auch mit weiteres. Das weitere besteht darin, dass C++-Funktionen mittels C-Bibliotheken gewrapped werden können. Und in meinem letzten...