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 "192.1.1.8" 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=192.1.1.8 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:

log.WithFields(log.Fields{
		"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")
apiLogger.WithFields(log.Fields{
		"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=192.1.1.8 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=192.1.1.8 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=192.1.1.8 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=192.1.1.8 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.

0 Kommentare

Trackbacks/Pingbacks

  1. Monthly Snap August – NETWAYS News | Tipps & Tricks | Upcoming… | Corporate Blogging › NETWAYS Blog - […] beschäftigt sich in The Walrus Has Landed mit Structured Logging in Go und Georg dank einer Kunden-Anfrage mit der…

Einen Kommentar abschicken

Deine E-Mail-Adresse wird nicht veröffentlicht. Erforderliche Felder sind mit * markiert

Mehr Beiträge zum Thema Golang

check_prometheus ist jetzt öffentlich verfügbar!

Monitoring ist komplex, das wissen wir hier bei NETWAYS leider zu gut. Deswegen laufen in der Infrastruktur auch mal gerne mehrere Tools für die Überwachung. Zwei gern gesehene Kandidaten sind dabei Icinga und Prometheus. Icinga und Prometheus erfüllen...

Neues zum go-check

Lang ist es her, dass ein Blogpost über das hauseigene NETWAYS go-check geschrieben wurde. Seitdem hat sich das go-check immer weiterentwickelt und wurde mit vielen verschiedenen Funktionen erweitert, sodass die Pluginentwicklung noch einfacher von der Hand geht. Um...