article about logging

.gitlab-ci.yml

@@ -1,13 +0,0 @@
-image: golang:1.12
-
-stages:
-  - test
-
-variables:
-  GO111MODULE: "on"
-
-test:
-  stage: test
-  script:
-    - cd ${CI_PROJECT_DIR}
-    - make

doc/logging-in-golang.adoc

@@ -0,0 +1,162 @@
+= My Take on Logging in Golang
+Erik Winter <ik@erikwinter.nl>
+2021-04-01
+:kind: tutorial
+:language: en
+:tags: golang
+
+The subject of logging comes up every now and then, in every group of developers. Apparently it is something to be opinionated about, like code formatting. Or to something complain about, like leaving off the cap of the toothpaste. If only there was a `go fmt` for logging. Or toothpaste.
+
+Anyway, as with most things computing, I like logging to be simple and pragmatic. Over the years, these are the things I’ve come to consider important with this subject.
+
+== Levels
+
+When thinking about what logging levels are appropriate, it helps to define the intended audience for a certain level and what information that audience should get out of it. In addition to that, it also helps to remember what goals and what information are already covered by other systems.
+
+For instance, logging is not to be confused with:
+
+* Alerting
+* Monitoring
+* Metrics
+
+If there are other systems in place to provide this functionality, adding information for it to the logs just increases the noise. If there are no other systems and you want to use logging for it, then make sure that  appropriate procedurees are in place, or the information will still be noise. For instance, what use has the logging of a warning, when there is no-one who actually gets warned and people only see it when they happen to stumble upon it when they are looking for someting else?
+
+What should be logged then and at what level? In https://dave.cheney.net/2015/11/05/lets-talk-about-logging[this article], Dave Cheney makes a good argument to minimize the logging interface and he states that the only useful levels are `debug` and `info`. However, he acknowledges that errors should be logged too and since we try to add structure to ours logs (see next section), it would be strange to log an `error` as `info` and then later use another way to add the semantic information that it is, in fact, an `error`.
+
+Together, this gives the following levels and their intended audience:
+
+* `debug` - Things that happened that developers care about when developing a feature, or fixing a bug.
+* `info` - Things that happened that users and administrators care about, that don’t impact the behavior of the application.
+* `error` - Things that happened that users care about, because they do impact behavior. For instance, a lost connection can be re-established by the application itself, but there could be a small delay.
+
+== Structured logging and standard log messages
+
+At minimum a log line is just a line of text. Preferably with a timestamp somewhere in it. But since there are a lot of them and they tend to grow into big haystacks that may or may not have a needle in them, it helps if we can use scripts and other automation to help us search and analyze them. Thus we want something that is easy to parse.
+
+I am not in favor of using JSON for everything everywhere, but I think this is an appropriate usecase. Everyline should be a line of JSON with some fields. One of the benefits of using JSON structured logging is that it becomes much easier to give context to a messages by adding data. Context can be very helpful when searching and filtering the logs, but this only works well if the data is labeled explicitly. 
+
+Any serious logging library (see also the next section) will provide a way to add fields to a message. Use this as much  as possible, because otherwise it will be hard to see from the logs what is message and what is context:
+
+----
+// without JSON structured logging
+logger.Printf("response with status %d received", response.Code)
+
+// output:
+2021-01-01 12:00:00 response with status 400 received
+
+// with JSON and levels, but without fields
+logger.Infof("response with status %d received", response.Code)
+
+// output:
+{
+  "level": "info",
+  "message": "response with status 400 received",
+  "time": "2021-01-01 12:00:00"
+}
+
+// with JSON, levels and fields
+logger.With(log.Fields{
+  "status": response.Code,
+}).Info("response received")
+
+// output:
+{
+  "level": "info",
+  "status": 400,
+  "message": "response received",
+  "time": "2021-01-01 12:00:00"
+}
+----
+
+The last example will be most useful when analyzing the logs, as we can now filter for an exact message (“response received“) and get all the variations of received status codes in one search. Usually, one does not know the exact reason that caused things to fail, that’s why we are analyzing after all. So we do not know the exact status code that we are looking for. Was the other server malfunctioning and did we receive a `500`? Or is our password expired and did we receive a `401`? When logging like the first couple of examples, we can only guess possible causes and try to predict the exact message before we can search for it. With the last approach, we just search for the message and then see what status was returned.
+
+After that, we could either create a count of the different codes (x times `200`, y times `500`, etc) and see how they are distributed, or narrow down the search  to a specific code. See https://erikwinter.nl/articles/2021/simple-log-file-analysis-for-your-kubernetes-pods-on-the-command-line/[this tutorial] for some pointers on how to do some useful quick analyses on the commandline.
+
+Errors are excellent candidates to put in a field. If the level of the message is error, there should be a field with key "error” present:
+
+----
+// verbose implementation
+logger.WithFields(log.Fields{
+  "error": err,
+}).Error("something did not work")
+
+// with shortcut method
+logger.WithErr(err).Error("something did not work")
+----
+
+== Wrapping loggers
+
+Another way to add structure is by wrapping loggers. Most loggers implement https://en.wikipedia.org/wiki/Method_chaining[method chaining] to provide what is called a fluent interface. That is, most methods on the logger have a new logger instance as a return type. We can use this to gradually add context as we pass the logger along:
+
+----
+// in main.go
+logger := log.NewLogger(os.Stdout).WithFields(log.Fields{
+  "service": "someservice",
+})
+
+m := something.New(logger, ...)
+
+// in something/something.go
+type SomeThing struct{
+  logger log.Logger
+  ...
+}
+
+func New(logger log.Logger, ...) *SomeThing {
+  ...
+  return &SomeThing{
+    logger: logger.WithFields(log.Fields{
+      "package": "something",
+    }),
+    ...
+  }
+}
+
+func (st *SomeThing) DoIt(...) {
+  logger := st.logger.WithFields(
+    "method": "doit",
+  )
+  ...
+  logger.Info("something was done")
+}
+----
+
+If you now ever encounter a message `“something was done“` in the logs, it will be accompanied by the fields  `"service":"someservice"`,  `"package":"something"` and `"method":"doit"`. It is not hard to imagine how this could help the debugging during an incident.
+
+== Advanced structuring
+
+There are more possibilities to add context and information, as can be seen from this example from the https://github.com/go-kit/kit/tree/master/log[go-kit log library]:
+
+----
+var logger log.Logger
+logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
+logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
+
+logger.Log("msg", "hello")
+
+// Output:
+// ts=2016-01-01T12:34:56Z caller=main.go:15 msg=hello
+----
+
+Here `log.DefaultTimestampUTC` and `log.DefaultCaller` are functions. With a logger that accepts a contextual function as a value, one can create any structure that might be interesting. The function gets evaluated when the message is logged and the output is what gets stored. This way it is possible to add custom timers, add stack traces, etc.
+
+== Injecting loggers versus returning errors
+
+As can be seen in the examples above, when building context it helps to treat a logger as an instance of type Logger and use it it to create new instances, instead of relying on a single logger that is globally present. A natural consequence of this is that a logger should be a parameter that is passed around whenever necessary. At first sight it seems cumbersome and verbose to do that everywhere in your code.
+
+However, it is not necessary to pass the logger to every part of the code, since not every part of the code has the need to log. If we examine a https://erikwinter.nl/notes/2021/my-default-golang-directory-structure/[basic directory structure for Go projects] and look what kind of packages each folder holds:
+
+----
+.
+├── cmd             // the different programs/services
+├── internal        // decoupled packages specific to this repository
+└── pkg             // decoupled packages that may be imported by other projects
+----
+
+Then we see that every action is initiated somewhere in `/cmd` and that the packages in `/internal` and `/pkg` are supposed to be decoupled from the rest. We can get by with the rule of thumb that the logging should be done in `/cmd` and that the packages in `/internal` and in `/pkg` should return errors that may or may not get wrapped and may or may not get logged when they arrive in `/cmd`. 
+
+Ever had some external library messing up things because they decided just to log to Stdout the way they saw fit? Not very helpful. If you https://erikwinter.nl/articles/2021/depend-less-on-dependencies-with-the-adapter-pattern-in-golang/[wrap external dependencies in an adapter], you can make sure that the errors also translate properly to the domain of your program. If a library really insists on having a logger and you still want to use it anyway, this is the place to add context.
+
+== Example implementation
+
+An example of how you can adapt a regular logging library to these practices is the `log` package in my https://git.sr.ht/~ewintr/go-kit[small personal go kit repository]. There is an interface definition in `log.go`, together with two implementations, one for https://github.com/Sirupsen/logrus[Logrus] and one for the https://gokit.io/[gokit.io] `log` package, and an implemention suitable for use in testing.