transport/http ServerFinalizer should accept error for better logging support

[drscre]

We have three systems where logs are sent: our internal ELK stack, NewRelic and Airbrake.
Some of our endpoints send errors to all of this systems, some endpoints send errors to only one of it.

We want log entries to have both error message and http status code. And also some http request context (uri, method, user-agent, ip...)

The only place which has access to both error and http status is ServerErrorEncoder.
But since different endpoints need different sets of log outputs, we would have to create multiple error encoders just for sake of logging. Also, ServerErrorEncoder is not a good place for logging, because we would like it to do only one job - encode errors.

ServerFinalizer seems to be a great place to send logs, but there is no access to actual error message.

[peterbourgon]

If you want your ServerFinalizer to act on information from the service domain (e.g. an error) you can inject that error into the context, and extract it again.

[drscre]

@peterbourgon
What is the proper way to inject endpoint error into context?
I can think only of using mutable (pointer to error interface) key in context and update it in middleware.

[peterbourgon]

Yes, basically. You might look at e.g. ctxlog for an example of something like this.

[drscre]

Thanks, this will work for endpoint errors.

But if i want to include request decoding errors as well, i will have to inject error into context in every request decoder (we do not generate them, unfortunatelly).

Probably, i will stick to logging in ErrorEncoder

Still, it would be nice to have error as an argument of Finalizer.

[peterbourgon]

If your RequestDecoder returns an error, it is given directly to the ErrorEncoder. Is that not sufficient?

[drscre]

Yes, it will work.

But since one of the main reasons finalizer exist is logging, i really would prefer to do it there.

[peterbourgon]

package main

import (
	"context"
	"encoding/json"
	"errors"
	"fmt"
	"net/http"
	"net/http/httptest"
	"os"
	"strings"

	"github.com/go-kit/kit/log"
	httptx "github.com/go-kit/kit/transport/http"
)

func main() {
	logger := log.NewLogfmtLogger(os.Stdout)

	kitserver := httptx.NewServer(
		// Endpoint, which just decides how to fail the request.
		func(ctx context.Context, request interface{}) (response interface{}, err error) {
			req := request.(myRequest)
			if req.FailTransport {
				return myResponse{}, errFailTransport
			}
			if req.FailService {
				return myResponse{Err: errFailService, Message: "plonk"}, nil
			}
			return myResponse{Message: "OK"}, nil
		},

		// Decoder is simple.
		func(ctx context.Context, r *http.Request) (request interface{}, err error) {
			var req myRequest
			json.NewDecoder(r.Body).Decode(&req) // error handling elided here
			return req, nil
		},

		// Encoder, which should set service error in errorContainer, if applicable.
		func(ctx context.Context, w http.ResponseWriter, response interface{}) error {
			resp := response.(myResponse)
			if resp.Err != nil {
				getErrorContainer(ctx).service = resp.Err
				w.WriteHeader(http.StatusTeapot)
			}
			return json.NewEncoder(w).Encode(resp)
		},

		// ServerBefore must inject the errorContainer to the context.
		httptx.ServerBefore(func(ctx context.Context, _ *http.Request) context.Context {
			return context.WithValue(ctx, errorContainerKey, &errorContainer{}) // new empty errorContainer with each request
		}),

		// ServerErrorEncoder must set transport error in the errorContainer.
		httptx.ServerErrorEncoder(func(ctx context.Context, err error, w http.ResponseWriter) {
			getErrorContainer(ctx).transport = err
			w.WriteHeader(http.StatusInternalServerError)
			fmt.Fprintf(w, `{"error":"%s"}\n`, err.Error()) // or whatever
		}),

		// ServerFinalizer consumes errorContainer.
		httptx.ServerFinalizer(func(ctx context.Context, code int, r *http.Request) {
			c := getErrorContainer(ctx)
			logger.Log("code", code, "transport_err", c.transport, "service_err", c.service)
		}),
	)

	stdserver := httptest.NewServer(kitserver)
	http.Post(stdserver.URL, "application/json; charset=utf-8", strings.NewReader(`{}`))
	http.Post(stdserver.URL, "application/json; charset=utf-8", strings.NewReader(`{"fail_transport":true}`))
	http.Post(stdserver.URL, "application/json; charset=utf-8", strings.NewReader(`{"fail_service":true}`))
}

type myRequest struct {
	FailTransport bool `json:"fail_transport"`
	FailService   bool `json:"fail_service"`
}

type myResponse struct {
	Err     error  `json:"-"`
	Message string `json:"message"`
}

var (
	errFailTransport = errors.New("transport-level failure")
	errFailService   = errors.New("business-level failure")
)

//
//
//

type errorContainer struct {
	transport error
	service   error
}

type errorContainerKeyType struct{}

var errorContainerKey errorContainerKeyType

func getErrorContainer(ctx context.Context) *errorContainer {
	v := ctx.Value(errorContainerKey)
	if v == nil {
		panic("no error container set")
	}
	c, ok := v.(*errorContainer)
	if !ok {
		panic("invalid error container")
	}
	return c
}

[peterbourgon]

$ go run error_example.go
code=200 transport_err=null service_err=null
code=500 transport_err="transport-level failure" service_err=null
code=418 transport_err=null service_err="business-level failure"

[drscre]

Thanks! This is more or less what i am trying to achieve.

But, again, what is wrong with having err as an argument to finalizer? (except compatibility break)

[peterbourgon]

It would break the API, and it would be inelegant and awkward to implement, especially if you wanted to capture both service- and transport-level errors.

[drscre]

I have a hard time grasping the concept of returning service errors inside response structure.

Why do we need this if endpoint has explicit error return argument?
How do i determine what is transport and what is service error (and do i really need to differentiate them)? Is DB query error transport or service?
Why don't we use some (painful in current Go) way to distinguish between error types (i.e. error implements some ServiceError interface)?

Regardless of whether it is a service or transport error, i would typically return the same error response from service.

In the regular Go code i don't see people returning errors as part of return argument structure.

[peterbourgon]

Transport errors are discoverable by endpoint- and transport-layer middlewares, and indicate a problem with the mechanics of the request. For example, the underlying service is unavailable, or a network gateway is down. They may be counted as errors from the perspective of an e.g. circuit breaker, and eventually cause further requests to fail until the error is resolved.

Service errors are not detectable by endpoint- and transport-layer middlewares, and indicate that the mechanics of the request were/are fine, but that there was a problem with the business logic. For example, a user attempted to withdraw too much money from their account. These errors don't indicate anything mechanically wrong with the service, the network, etc. and so shouldn't count toward a circuit breaker limit.

Another way of thinking of it: given some request, transport errors can be automatically retried because they might go away by themselves (e.g. 502 Bad Gateway), but service errors should not be because they won't go away unless either the request or the state of the service changes (e.g. 401 Bad Request).

edit: But I understand that this distinction may be more noise than signal to many developers. A future version of Go kit may eliminate it, or encode it in a different way.