Logging in go-api-basic

Thoughts on Logging

I’ve gone through a few logging phases in my career. I logged everything. It was great, until the logs became meaningless because there were too many. I logged only errors, but in some cases that was not enough. Now I’m somewhere in the middle. I do believe in logging all errors and detailed how I do that in my last post. There are also times when it’s helpful to have some debugging logs in place. As an example, if you’ve ever tried to build a google doc using their APIs, then you may know that it can be helpful to have some tidbits of information about the document index position along your code/document path. In cases like this, I will leave debug logs in place in order to be able to pull the thread on them later if need be. Often times, I may deploy a change with some logs in place until I’ve seen enough data in action in production and then back out the logs in the next change when I’m satisfied. In general, I try to minimize the amount of logging in my code and only put logs in where it counts.

Logging in go-api-basic with zerolog

go-api-basic uses the zerolog library from Olivier Poitrey. I’m not gonna lie - initially, I chose this library because Olivier uses it at Netflix and that was enough for me. Over time though, I’ve really come to love this logging library and Olivier is a great maintainer. I spent a lot of time a couple of years ago helping with the README and a number of other things in the library along the way. I’ve learned a lot about Go and open source just from these interactions. If I use a library, I generally try to give back in some way to it, but often times through these interactions, I get back more in return, actually.

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

When starting go-api-basic, there are several flags which setup the logger:

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

The Server.routes method is responsible for registering routes and corresponding middleware/handlers to the Server’s gorilla/mux router. For each route registered to the handler, upon execution, the initialized zerolog.Logger struct is added to the request context through the Server.loggerChain method.

// 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.

func (s *Server) loggerChain() alice.Chain {
    ac := alice.New(hlog.NewHandler(s.logger),
        hlog.AccessHandler(func(r *http.Request, status, size int, duration time.Duration) {
        hlog.FromRequest(r).Info().
            Str("method", r.Method).
            Stringer("url", r.URL).
            Int("status", status).
            Int("size", size).
            Dur("duration", duration).
            Msg("request logged")
        }),
        hlog.RemoteAddrHandler("remote_ip"),
        hlog.UserAgentHandler("user_agent"),
        hlog.RefererHandler("referer"),
        hlog.RequestIDHandler("request_id", "Request-Id"),
    )

    return ac
}

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

{
    "level": "info",
    "remote_ip": "127.0.0.1",
    "user_agent": "PostmanRuntime/7.28.0",
    "request_id": "c3npn8ea0brt0m3scvq0",
    "method": "POST",
    "url": "/api/v1/movies",
    "status": 401,
    "size": 0,
    "duration": 392.254496,
    "time": 1626315682,
    "severity": "INFO",
    "message": "request logged"
}

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:

{
    "level": "error",
    "remote_ip": "127.0.0.1",
    "user_agent": "PostmanRuntime/7.28.0",
    "request_id": "c3nppj6a0brt1dho9e2g",
    "error": "googleapi: Error 401: Request is missing required authentication credential. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project., unauthorized",
    "http_statuscode": 401,
    "realm": "go-api-basic",
    "time": 1626315981,
    "severity": "ERROR",
    "message": "Unauthenticated Request"
}

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

You can retrieve and update the state of these flags using the {{base_url}}/api/v1/logger endpoint.

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:

{
    "logger_minimum_level": "debug",
    "global_log_level": "error",
    "log_error_stack": false
}

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:

{
    "logger_minimum_level": "debug",
    "global_log_level": "debug",
    "log_error_stack": true
}

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.