Logrus Logger from Context

[domgreen]

I would like to be able to add and retrieve a logger from the context and therefore not have to pass a logger through all function calls but get it off the context when it is needed. Most of the time a logger and its attached fields are request scoped so feels like it fits in well being stored on the context. Methods for doing this would look something like:

func Extract(ctx context.Context) *Entry

func ToContext(ctx context.Context, entry *Entry)

We currently have an implementation that does this for our http and gRPC middleware projects that can be seen here:

https://github.com/improbable-eng/go-httpwares/tree/master/logging/logrus/ctxlogrus

This allows our interceptors to attach a entry onto the context and use all the fields for the duration of the calls.

[morganchristiansson]

Duplicates #488 see this comment for solution: https://github.com/sirupsen/logrus/issues/488#issuecomment-300632875

[stevvooe]

https://github.com/containerd/containerd/blob/master/log/context.go provides a nice pattern you can add to each project. Since its orthogonal to the logger, I am not sure about integrating it with logrus.

[imax9000]

+1 for adding this functionality into logrus. Rationale: it is useful to have Entry (fields that are set in it in particular) carried across package boundaries, e.g. for request tracing. But we will get that benefit only if everyone uses the same package for updating/reading context and putting this into logrus directly is one way of avoiding fragmentation.

As of today, I've implemented a package with exactly the same functionality as mentioned in the first comment simply because I don't want to depend on that whole repo for just one tiny package.

[sebfan2]

Wouldn't providing functions for setting and getting an entire Entry instance from ctx be encouraging ctx to be used as dependency injection method for logging? It couples any package that wants to retrieve the information with logrus, coupling trace information with actual logging implementations.

But we will get that benefit only if everyone uses the same package for updating/reading context and putting this into logrus directly is one way of avoiding fragmentation.

I really think that end result should be avoided and the solution to carrying trace information through ctx shouldn't be dependent on everyone importing the same logging package, or any logging package at all.

Some related reading (including the group discussion linked within): https://dave.cheney.net/2017/01/26/context-is-for-cancelation

[freeformz]

I'm quoted in that Dave Cheney post. So...

Yes, loggers should be injected into dependencies. Full Stop.

But ... How do you allow http middleware and the like to add request specific items to the logger? This is the perfect use for storing and retrieving a logrus.Entry to/from a context.Context. IMO It aligns well with other guidance on Context : https://dave.cheney.net/2017/08/20/context-isnt-for-cancellation

The guidance I give teams when asked about this is:

1. Create and inject the root logger into your types. This allows configuration of the logger in main based on usage and deployment needs.

2. If you collect/determine request scoped info in your handler w/o middleware, then just take the root logger in the handler's constructor and use that. Only do the following things if you need to append request scoped data to your logger when using middleware or similar constructs:

   1. Provide middleware that uses the injected logger to create a request specific logrus.Entry that is stored in the context. This middleware should be at the top of the stack, or close to it.
   2. Provide a function that allows down chain middleware and / or the final handler to retrieve the request specific logger from the context.
   3. Provide a function, or functions, that adds a field or fields to the logrus.Entry stored in the context (and returns the updated logrus.Entry). This allows other middleware to add their own fields/data to the logger.
   4. If you are in this type of middleware or handler, only use the logger returned by the functions created in 3.

[sebfan2]

One way we've handled this in the past is by putting the request scoped data in context and then later passing context to any logger that needed it. Similar to the middleware outline above, the difference being only request scoped data itself was stored in the context rather than an entire logging implementation.

Doing this ensured

• Packages that needed request scoped trace data did not require logging at all, or could use their own custom logging impl yet still have the same request scoped data available to log.

• Logging was injected into packages only on instantiation, there was only 1 method for grabbing a logger and it was tested like any other dependency. Any package could log something request scoped using only its injected logger.

• Logging with request scope just meant passing the context to the log, the same way context is always passed around in Go, developers were familiar with its usage pattern. Nicely idiomatic.

This is just one example, and either approach works in the end, the result is the same. I just personally don't advocate an external package (logrus in this case) channelling itself around an app inside context, there is too much coupling IMO and it results in more than one way to get a logger.

[pellared]

One of Go's main advantage (and I would say also principle) is ease-of-use. I find contextual logging very pragmatic and easy to plug-in to an existing application. https://github.com/containerd/containerd/blob/master/log/context.go looks very good. I have written almost identical code without knowing it: https://github.com/pellared/logrusutil

Take notice that the first Go Experience Report for Context (https://github.com/golang/go/wiki/ExperienceReports#Context) is https://blog.gopheracademy.com/advent-2016/context-logging/

Generally tightly coupling the application to a logging library is not "that bad". Here is a great blog post which deeply explains why: https://nblumhardt.com/2016/04/which-logging-abstraction-should-i-use the author is an authority in .NET ecosystem - he created stuff like Serilog (first popular semantic/structured logging library in .NET), Autofac (IoC Container).

loggers should be injected into dependencies

While I agree with most of Dave's concepts here I would definitely say: "it depends". In most of the enterprise software logging is not critical and almost never unit tested. It is just an addition for troubleshooting. It is a kind of cross-cutting concern where I do not need DI. For SOLID fanatics I would say that even injecting a logger is not enough because a class/object/struct should have a single responsibility and require only dependencies to "do the work" (https://blog.ploeh.dk/2018/08/27/on-constructor-over-injection/) - it should be implemented as a Decorator 😈 .

Take notice that a lot of application tracing/instrumentation in Go is done using the context.

[sebfan2]

One of Go's main advantage (and I would say also principle) is ease-of-use.

I agree, but I'd also strongly argue that ctx being a channel for a logging (or any) dependency is substantially less clear and less easy to use. Any function that accepts a logger (or anything else) through ctx effectively has a hidden argument that is neither checked by the compiler, nor telegraphed to the function consumer. Necessarily that function now has the responsibility of having to extract what it wants out of ctx and handle any errors or the possibility of it not existing. This places much more responsibility on both the function and caller. However you dice this, it is more code and less transparent.

Someone just wrote a talk outlining exactly the solution I did previously:

https://www.youtube.com/watch?v=NxNT1-S-tKg&list=PLeGxIOPLk9EL4BDb-8tAUY2YYv0aVgTXY&index=3&t=0s

Simpler, clearer, and more idiomatic context usage.

[pellared]

@sebfan2 First of all. Thanks for your comment. I really appreciate it.

However, I do not see any significant difference between what I described (https://github.com/go-logrusutil/logrusutil) and the talk that you posted (https://www.youtube.com/watch?v=NxNT1-S-tKg&list=PLeGxIOPLk9EL4BDb-8tAUY2YYv0aVgTXY&index=3&t=0s)

It is like for logging:

logctx.From(ctx).Info("log me")

vs

logger.Info(ctx, "log")

And for adding contextual log field:

newCtx := logctx.New(ctx, logctx.From(ctx).WithField("data", 123)) // for threat-safety, required if we want to use the context in new goroutine
// or
logctx.From(ctx).Data["data"] = 123 // if we care about perfomance and want to mutate the contextual log entry

vs

newCtx := logger.WithFields(ctx, logger.Fields{"data" : 123}) 

Or maybe I am missing something important? I think that there are just only little API differences and both solutions contain the log entry in the context.

[sebfan2]

With this line:

logctx.From(ctx).Info("log me")

A logger is being extracted from inside the context and then being used. The behavior is dependent on what is in context, logging is dependent on context.

With this line:

logger.Info(ctx, "log")

A logger is receiving a context for use. The logger itself is not inside context and can be any logger. Any context can be passed, including empty, with no change in behavior.

[drewwells]

Implemented in the ctxlogrus middleware https://godoc.org/github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus

[markphelps]

Closing per the project being put into maintenance mode