Logging with request context

[drscre]

I would like to add some request information to my error log messages (http url / endpoint name / request params)

What is the proper way to do this? With http.ServerErrorLogger() I have no access to context

[peterbourgon]

Where are you invoking your error logging?

[drscre]

I registered logger using http.ServerErrorLogger() when creating http.NewServer()

Of course I can log errors via custom error logging middleware. But it will miss request encoding/decoding errors.
I can as well do logging in errorEncoder(), but it does not seem to be an appropriate place.

[peterbourgon]

After review the code and your use case, I think if you explicitly want rich error logging, the correct place to do that is in a custom error encoder. The ErrorEncoder is meant for basic diagnostics, and may even be a candidate for deletion. But the error encoder will always be called in case of error, it has access to everything you want, and I think it's the right place for this kind of logic.

In #408 I've clarified this in the docs and also added ServerFinalizer, which is a function that can do arbitrary work (including logging) once a request is complete. If you rather want comprehensive logging or instrumentation of the HTTP transport layer, you can also use that mechanism.

[drscre]

Ok, so the only way to get both error and context is to use custom error encoder.

My point about error encoder was that, without looking into the code, its' contract is not entirely obvious. Judging by the name I would expect that it should convert errors to http responses and have no side effects.
But can I be sure that it will be called only once for an error that actually occurs?

Having something like afterError() would be more obvious. Or, even better, transport-level middlewares.

Another solution would be to add context to already existing logging functionality.
Like s.logger.Log("err", err, "context", ctx) instead of s.logger.Log("err", err)

I think that enriching log messages with request context is a pretty common use case.

[peterbourgon]

I think you are giving the transport layer too much responsibility. Ideally, package transport would be responsible for request/response de/serialization and nothing more. Certain out-of-band metadata e.g. distributed tracing IDs require additional facilities to move information to/from the context i.e. Server{Before,After}Func — but anything more sophisticated than that belongs in your business logic. Transport-layer middlewares would be a big step in the wrong direction.

More concretely, you probably ought to move the loggable details from the HTTP request into the context via a BeforeFunc, potentially even into a request-scoped logger object. Then, extract/use those details in your business logic when your error condition is encountered, rather than waiting until the request returns to the transport layer on the way out. Your business logic error to HTTP status code mapping should be well-defined in your business logic — the clean architecture and inward-facing dependencies require it — so you can even determine status code a priori and log it there, too. And thus let the transport layer be mechanical, concerned with rote shuffling of data.

Can you say a bit more about the specific error conditions you're trying to enrich with this information? I'd be happy to consult a bit, or offer another solution if I'm overlooking something...

[drscre]

Actually, that's similar to how I do logging now.
First a BeforeFunc moves required details into the context (tracing id, raw request).
Then there is a logging middleware for all endpoints that actually logs errors and adds endpoint name to log messages.

The problem is that this does not catch transport decoding errors. One of my microservices was sending invalid requests that failed at request decoding step.
Having this error logged with endpoint name and raw request would have simplified debugging the problem.

[drscre]

Or, to put it short, I would like transport errors to be logged in the same way the business logic errors are.

[drscre]

What's wrong with supporting transport-level middlewares?
We already have BeforeFunc and AfterFunc, and it seems to me that
BeforeFunc + AfterFunc ~ Middleware

[peterbourgon]

I'm giving this a think.

[peterbourgon]

I mean you don't need explicit support for middlewares in package transport/http, you can just use them.

var handler http.Handler
handler = httptransport.NewServer(...)
handler = myBasicMiddleware(handler)
handler = myParameterizedMiddleware(...)(handler)
mux.Method("GET").Path("/foo").Handler(handler)

[peterbourgon]

I've also added PopulateRequestContext helper, to get HTTP request details into the context. Hopefully this is enough to help you build something that works :)

[drscre]

With "classic" middleware I don't have errors and i don't have context.

Ok, I will stick to ErrorEncoder

[peterbourgon]

You do have context, with the Context method on http.Request. (I'll upgrade Go kit to support that more fully when 1.8 is released.) And you can get errors, by intercepting the http.ResponseWriter.

[peterbourgon]

#421 for using stdlib context, currently pending changes in gRPC (argh).