Logging in go-api-basic

A bearded gopher with a lightsaber cutting up some logs

Thoughts on Logging

Logging in go-api-basic with zerolog

The mechanics for using zerolog are straightforward and are well documented in the library's README. zerolog takes an io.Writer as input to create a new logger; for simplicity in go-api-basic, I use os.Stdout.

Setting Logger State on Startup

go-api-basic uses the ff library from Peter Bourgon, which allows for using either flags or environment variables. Click here if you want more info on this setup. Going forward, we'll assume you've chosen flags.

The log-level flag sets the Global logging level for your zerolog.Logger.

zerolog allows for logging at the following levels (from highest to lowest):

  • panic (zerolog.PanicLevel, 5)
  • fatal (zerolog.FatalLevel, 4)
  • error (zerolog.ErrorLevel, 3)
  • warn (zerolog.WarnLevel, 2)
  • info (zerolog.InfoLevel, 1)
  • debug (zerolog.DebugLevel, 0)
  • trace (zerolog.TraceLevel, -1)

The log-level-min flag sets the minimum accepted logging level, which means, for example, if you set the minimum level to error, the only logs that will be sent to your chosen output will be those that are greater than or equal to error ( error, fatal and panic).

The log-error-stack boolean flag tells whether to log stack traces for each error. If true, the zerolog.ErrorStackMarshaler will be set to pkgerrors.MarshalStack which means, for errors raised using the github.com/pkg/errors package, the error stack trace will be captured and printed along with the log. All errors raised in go-api-basic are raised using github.com/pkg/errors.

After parsing the command line flags, zerolog.Logger is initialized in main.go

// setup logger with appropriate defaults
lgr := logger.NewLogger(os.Stdout, minlvl, true)

and subsequently injected into the app.Server struct as a Server parameter.

// initialize server configuration parameters
params := app.NewServerParams(lgr, serverDriver)
// initialize Server
s, err := app.NewServer(mr, params)
if err != nil {
lgr.Fatal().Err(err).Msg(“Error from app.NewServer”)
}

Logger Setup in Handlers

// register routes/middleware/handlers to the Server router
func (s *Server) routes() {
// Match only POST requests at /api/v1/movies
// with Content-Type header = application/json
s.router.Handle(moviesV1PathRoot,
s.loggerChain().Extend(s.ctxWithUserChain()).
Append(s.authorizeUserHandler).
Append(s.jsonContentTypeResponseHandler).
ThenFunc(s.handleMovieCreate)).
Methods(http.MethodPost).
Headers(contentTypeHeaderKey, appJSONContentTypeHeaderVal)
...

The Server.loggerChain method sets up the logger with pre-populated fields, including the request method, url, status, size, duration, remote IP, user agent, referer. A unique Request ID is also added to the logger, context and response headers.

For every request, you’ll get a request log that looks something like the following:

All error logs will have the same request metadata, including request_id. The Request-Id is also sent back as part of the error response as a response header, allowing you to link the two. An error log will look something like the following:

The above error log demonstrates a log for an error with stack trace turned off.

If the logger is to be used beyond the scope of the handler, it should be pulled from the request context in the handler and sent as a parameter to any inner calls. The Logger is added only to the request context to capture request related fields with the Logger and be able to pass the initialized logger and middleware handlers easier to the app/route handler. Additional use of the logger should be directly called out in function/method signatures so there are no surprises. All logs from the logger passed down get the benefit of the request metadata though, which is great!

Reading and Modifying Logger State

To retrieve the current logger state use a GET request:

curl --location --request GET 'http://127.0.0.1:8080/api/v1/logger' \ --header 'Authorization: Bearer <REPLACE WITH ACCESS TOKEN>'

and the response will look something like:

In order to update the logger state use a PUT request:

curl --location --request PUT 'http://127.0.0.1:8080/api/v1/logger' \ --header 'Content-Type: application/json' \ --header 'Authorization: Bearer <REPLACE WITH ACCESS TOKEN>' \ --data-raw '{ "global_log_level": "debug", "log_error_stack": "true" }'

and the response will look something like:

The PUT response is the same as the GET response, but with updated values. In the examples above, I used a scenario where the logger state started with the global logging level ( global_log_level) at error and error stack tracing ( log_error_stack) set to false. The PUT request then updates the logger state, setting the global logging level to debug and the error stack tracing. You might do something like this if you are debugging an issue and need to see debug logs or error stacks to help with that.

Peter Bourgon recently tweeted the above about github.com/pkg/errors. He's not wrong. In general the standard library is always the way to go. For years I only used the standard library for raising errors and would annotate each error with the function name in order to capture a pseudo stack trace exactly like Rob Pike does in this post (the errs.Op field). I believe in annotating and logging every error - not everyone does. It can cause noise in your logs, but in my experience, it's helpful. After years of trying to annotate every error though, I found I made too many mistakes. I kept forgetting to log the function name or I would misspell it, etc. I switched to use github.com/pkg/errors because of it's stack trace capability as well as the integration zerolog has with it. Stack trace for errors can certainly be overkill though, hence the ability to turn it on/off with a service for tactical usage can come in handy.

No actual logs were harmed in this post.

Originally published at https://dangillis.dev on July 13, 2021.

Go enthusiast; Loyalty/CRM Technology Leader; Drummer; Vinyl geek; Husband/Dad