Forem: Dan Gillis

Logging in go-api-basic

Dan Gillis — Tue, 13 Jul 2021 20:06:49 +0000

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:

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")
}

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.

✕✕✕✕✕

@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

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.

REST API Error Handling in Go

Dan Gillis — Mon, 21 Jun 2021 14:48:56 +0000

Handling errors is really important in Go. Errors are first class citizens and there are many different approaches for handling them. Initially I started off basing my error handling almost entirely on a blog post from Rob Pike and created a carve-out from his code to meet my needs. It served me well for a long time, but found over time I wanted a way to easily get a stacktrace of the error, which led me to Dave Cheney's https://github.com/pkg/errors package. I now use a combination of the two. The implementation below is sourced from my go-api-basic repo, indeed, this post will be folded into its README as well.

Requirements

My requirements for REST API error handling are the following:

Requests for users who are not properly authenticated should return a 401 Unauthorized error with a WWW-Authenticate response header and an empty response body.
Requests for users who are authenticated, but do not have permission to access the resource, should return a 403 Forbidden error with an empty response body.
All requests which are due to a client error (invalid data, malformed JSON, etc.) should return a 400 Bad Request and a response body which looks similar to the following:

{
    "error": {
        "kind": "input_validation_error",
        "param": "director",
        "message": "director is required"
    }
}

All requests which incur errors as a result of an internal server or database error should return a 500 Internal Server Error and not leak any information about the database or internal systems to the client. These errors should return a response body which looks like the following:

{
    "error": {
        "kind": "internal_error",
        "message": "internal server error - please contact support"
    }
}

All errors should return a Request-Id response header with a unique request id that can be used for debugging to find the corresponding error in logs.

Implementation

All errors should be raised using custom errors from the domain/errs package. The three custom errors correspond directly to the requirements above.

Typical Errors

Typically, errors raised throughout go-api-basic are the custom errs.Error, which looks like:

type Error struct {
    // User is the username of the user attempting the operation.
    User UserName
    // Kind is the class of error, such as permission failure,
    // or "Other" if its class is unknown or irrelevant.
    Kind Kind
    // Param represents the parameter related to the error.
    Param Parameter
    // Code is a human-readable, short representation of the error
    Code Code
    // The underlying error that triggered this one, if any.
    Err error
}

These errors are raised using the E function from the domain/errs package. errs.E is taken from Rob Pike's upspin errors package (but has been changed based on my requirements). The errs.E function call is variadic and can take several different types to form the custom errs.Error struct.

Here is a simple example of creating an error using errs.E:

err := errs.E("seems we have an error here")

When a string is sent, an error will be created using the errors.New function from github.com/pkg/errors and added to the Err element of the struct, which allows retrieval of the error stacktrace later on. In the above example, User, Kind, Param and Code would all remain unset.

You can set any of these custom errs.Error fields that you like, for example:

func (m *Movie) SetReleased(r string) (*Movie, error) {
    t, err := time.Parse(time.RFC3339, r)
    if err != nil {
        return nil, errs.E(errs.Validation,
            errs.Code("invalid_date_format"),
            errs.Parameter("release_date"),
            err)
    }
    m.Released = t
    return m, nil
}

Above, we used errs.Validation to set the errs.Kind as Validation. Valid error Kind are:

const (
    Other           Kind = iota // Unclassified error. This value is not printed in the error message.
    Invalid                     // Invalid operation for this type of item.
    IO                          // External I/O error such as network failure.
    Exist                       // Item already exists.
    NotExist                    // Item does not exist.
    Private                     // Information withheld.
    Internal                    // Internal error or inconsistency.
    BrokenLink                  // Link target does not exist.
    Database                    // Error from database.
    Validation                  // Input validation error.
    Unanticipated               // Unanticipated error.
    InvalidRequest              // Invalid Request
)

errs.Code represents a short code to respond to the client with for error handling based on codes (if you choose to do this) and is any string you want to pass.

errs.Parameter represents the parameter that is being validated or has problems, etc.

Note in the above example, instead of passing a string and creating a new error inside the errs.E function, I am directly passing the error returned by the time.Parse function to errs.E. The error is then added to the Err field using errors.WithStack from the github.com/pkg/errors package. This will enable stacktrace retrieval later as well.

There are a few helpers in the errs package as well, namely the errs.MissingField function which can be used when validating missing input on a field. This idea comes from this Mat Ryer post and is pretty handy.

Here is an example in practice:

// IsValid performs validation of the struct
func (m *Movie) IsValid() error {
    switch {
    case m.Title == "":
        return errs.E(errs.Validation, errs.Parameter("title"), errs.MissingField("title"))

The error message for the above would read title is required

There is also errs.InputUnwanted which is meant to be used when a field is populated with a value when it is not supposed to be.

Typical Error Flow

As errors created with errs.E move up the call stack, they can just be returned, like the following:

func inner() error {
    return errs.E("seems we have an error here")
}

func middle() error {
    err := inner()
    if err != nil {
        return err
    }
    return nil
}

func outer() error {
    err := middle()
    if err != nil {
        return err
    }
    return nil
}

In the above example, the error is created in the inner function - middle and outer return the error as is typical in Go.

You can add additional context fields (errs.Code, errs.Parameter, errs.Kind) as the error moves up the stack, however, I try to add as much context as possible at the point of error origin and only do this in rare cases.

Handler Flow

At the top of the program flow for each service is the app service handler (for example, Server.handleMovieCreate). In this handler, any error returned from any function or method is sent through the errs.HTTPErrorResponse function along with the http.ResponseWriter and a zerolog.Logger.

For example:

response, err := s.CreateMovieService.Create(r.Context(), rb, u)
if err != nil {
    errs.HTTPErrorResponse(w, logger, err)
    return
}

errs.HTTPErrorResponse takes the custom error (errs.Error, errs.Unauthenticated or errs.UnauthorizedError), writes the response to the given http.ResponseWriter and logs the error using the given zerolog.Logger.

return must be called immediately after errs.HTTPErrorResponse to return the error to the client.

Typical Error Response

For the errs.Error type, errs.HTTPErrorResponse writes the HTTP response body as JSON using the errs.ErrResponse struct.

// ErrResponse is used as the Response Body
type ErrResponse struct {
    Error ServiceError `json:"error"`
}

// ServiceError has fields for Service errors. All fields with no data will
// be omitted
type ServiceError struct {
    Kind    string `json:"kind,omitempty"`
    Code    string `json:"code,omitempty"`
    Param   string `json:"param,omitempty"`
    Message string `json:"message,omitempty"`
}

When the error is returned to the client, the response body JSON looks like the following:

{
    "error": {
        "kind": "input_validation_error",
        "code": "invalid_date_format",
        "param": "release_date",
        "message": "parsing time \"1984a-03-02T00:00:00Z\" as \"2006-01-02T15:04:05Z07:00\": cannot parse \"a-03-02T00:00:00Z\" as \"-\""
    }
}

In addition, the error is logged. If zerolog.ErrorStackMarshaler is set to log error stacks (more about this in a later post), the logger will log the full error stack, which can be super helpful when trying to identify issues.

The error log will look like the following (I cut off parts of the stack for brevity):

{
    "level": "error",
    "ip": "127.0.0.1",
    "user_agent": "PostmanRuntime/7.26.8",
    "request_id": "bvol0mtnf4q269hl3ra0",
    "stack": [{
        "func": "E",
        "line": "172",
        "source": "errs.go"
    }, {
        "func": "(*Movie).SetReleased",
        "line": "76",
        "source": "movie.go"
    }, {
        "func": "(*MovieController).CreateMovie",
        "line": "139",
        "source": "create.go"
    }, {
    ...
    }],
    "error": "parsing time \"1984a-03-02T00:00:00Z\" as \"2006-01-02T15:04:05Z07:00\": cannot parse \"a-03-02T00:00:00Z\" as \"-\"",
    "HTTPStatusCode": 400,
    "Kind": "input_validation_error",
    "Parameter": "release_date",
    "Code": "invalid_date_format",
    "time": 1609650267,
    "severity": "ERROR",
    "message": "Response Error Sent"
}

Note: E will usually be at the top of the stack as it is where the errors.New or errors.WithStack functions are being called.

Internal or Database Error Response

There is logic within errs.HTTPErrorResponse to return a different response body if the errs.Kind is Internal or Database. As per the requirements, we should not leak the error message or any internal stack, etc. when an internal or database error occurs. If an error comes through and is an errs.Error with either of these error Kind or is unknown error type in any way, the response will look like the following:

{
    "error": {
        "kind": "internal_error",
        "message": "internal server error - please contact support"
    }
}

Unauthenticated Errors

type UnauthenticatedError struct {
    // WWWAuthenticateRealm is a description of the protected area.
    // If no realm is specified, "DefaultRealm" will be used as realm
    WWWAuthenticateRealm string

    // The underlying error that triggered this one, if any.
    Err error
}

The spec for 401 Unauthorized calls for a WWW-Authenticate response header along with a realm. The realm should be set when creating an Unauthenticated error. The errs.NewUnauthenticatedError function initializes an UnauthenticatedError.

I generally like to follow the Go idiom for brevity in all things as much as possible, but for Unauthenticated vs. Unauthorized errors, it's confusing enough as it is already, I don't take any shortcuts.

func NewUnauthenticatedError(realm string, err error) *UnauthenticatedError {
    return &UnauthenticatedError{WWWAuthenticateRealm: realm, Err: err}
}

Unauthenticated Error Flow

The errs.Unauthenticated error should only be raised at points of authentication as part of a middleware handler. I will get into application flow in detail later, but authentication for go-api-basic happens in middleware handlers prior to calling the app handler for the given route.

The WWW-Authenticate realm is set to the request context using the defaultRealmHandler middleware in the app package prior to attempting authentication.
Next, the Oauth2 access token is retrieved from the Authorization http header using the accessTokenHandler middleware. There are several access token validations in this middleware, if any are not successful, the errs.Unauthenticated error is returned using the realm set to the request context.
Finally, if the access token is successfully retrieved, it is then converted to a User via the GoogleAccessTokenConverter.Convert method in the gateway/authgateway package. This method sends an outbound request to Google using their API; if any errors are returned, an errs.Unauthenticated error is returned.

In general, I do not like to use context.Context, however, it is used in go-api-basic to pass values between middlewares. The WWW-Authenticate realm, the Oauth2 access token and the calling user after authentication, all of which are request-scoped values, are all set to the request context.Context.

Unauthenticated Error Response

Per requirements, go-api-basic does not return a response body when returning an Unauthenticated error. The error response from cURL looks like the following:

HTTP/1.1 401 Unauthorized
Request-Id: c30hkvua0brkj8qhk3e0
Www-Authenticate: Bearer realm="go-api-basic"
Date: Wed, 09 Jun 2021 19:46:07 GMT
Content-Length: 0

Unauthorized Errors

type UnauthorizedError struct {
    // The underlying error that triggered this one, if any.
    Err error
}

The errs.NewUnauthorizedError function initializes an UnauthorizedError.

Unauthorized Error Flow

The errs.Unauthorized error is raised when there is a permission issue for a user when attempting to access a resource. Currently, go-api-basic's placeholder authorization implementation Authorizer.Authorize in the domain/auth package performs rudimentary checks that a user has access to a resource. If the user does not have access, the errs.Unauthorized error is returned.

Per requirements, go-api-basic does not return a response body when returning an Unauthorized error. The error response from cURL looks like the following:

HTTP/1.1 403 Forbidden
Request-Id: c30hp2ma0brkj8qhk3f0
Date: Wed, 09 Jun 2021 19:54:50 GMT
Content-Length: 0

404 Error Illustration by Pixeltrue from Ouch!