24
Logging in go-api-basic
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.
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
.
When starting go-api-basic
, there are several flags which setup the logger:
Flag Name | Description | Environment Variable | Default |
---|---|---|---|
log-level | zerolog logging level (debug, info, etc.) | LOG_LEVEL | debug |
log-level-min | sets the minimum accepted logging level | LOG_LEVEL_MIN | debug |
log-error-stack | If true, log full error stacktrace, else just log error | LOG_ERROR_STACK | false |
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")
}
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!
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.
✕✕✕✕✕@peterbourgon#golang modules you probably shouldn't use
github.com/pkg/errors — basically superseded by 1.13+ stdlib package errors
github.com/uber-go/fx, github.com/google/wire — plain DI with interfaces/mocks is strictly superior almost always (exceptions know they're exceptions)03:39 AM - 03 Jul 2021
No actual logs were harmed in this post.
24