Logging with context values

[ziyaozclk]

We want to use the values such as CorrelationId, RequestPath, etc. of each incoming request in web service projects, when we trigger log logEvent anywhere in the application. Because we need these values to observe in what case the log event is thrown. For this, we do not want to use zap.WithField in the middleware and create a new logger to use values such as CorrelationId, RequestPath etc. and move them within the application with the context. This both corrects the cost of creating a new instance and we will need to do reflection in the places we will use for the logger object we carry in the context.

1-) We can add the like following method in the options file.

func Context(contextFunc func(ctx context.Context) []Field) Option {
	return optionFunc(func(log *Logger) {
		log.contextFunc = contextFunc
	})
}

2-) We should add contextFunc to logger file. This function will control how the values added to the context in the middleware are transformed.

contextFunc func(ctx context.Context) []Field

Finally, we must create methods such as Info, Error, Warn, Panic etc. so that they can take context parameters.

For Example;

func (log *Logger) InfoCtx(ctx context.Context, msg string, fields ...Field) {
	generatedFields := log.generateFields(ctx, fields...)
	log.Info(msg, generatedFields...)
}

func (log *Logger) generateFields(ctx context.Context, fields ...Field) []Field {
	if ctx != nil && log.contextFunc != nil {
		contextFields := log.contextFunc(ctx)
		return append(contextFields, fields...)
	}
	return nil
}

Use Example;

  ctx := context.TODO()
  ctx = context.WithValue(ctx, "Correlation-ID", "e9718aab-aa1a-4ad8-b1e6-690f6c43bd15")

  logger.InfoCtx(ctx, "Hello Zap Logger Community !!!")

Console Result;

{"level":"info","ts":1633699393.396655,"caller":"zap/logger.go:252","msg":"Hello Zap Logger Community !!!","Correlation-ID":"e9718aab-aa1a-4ad8-b1e6-690f6c43bd15"}

It works very well. 🚀🚀

I'm waiting for a reply as soon as possible.

[CLAassistant]

All committers have signed the CLA.

[polanskya]

upvoting this.. logging with context is highly desirable.. if you can prioritize this .. would be awesome.. thanks

[cideM]

For this, we do not want to use zap.WithField in the middleware and create a new logger to use values such as CorrelationId, RequestPath etc. and move them within the application with the context.

Why not? What is the cost of creating a new instance? To me it seems like the middleware approach is perfectly fine here.

[ziyaozclk]

Hi @cideM, Is it the right approach to create a new object on every request? I'm talking about a service that receives millions of requests

[cideM]

@ziyaozclk I'd start with a benchmark which would also make for a great case in this issue and show other people what impact they can expect for this. I'm not sure if the current zap README mentions the cost of sub-logger creation and if not it could also be amended with a benchmark.

[ziyaozclk]

@cideM You're right. Thank you for your suggestion. I'll share the performance benchmark as soon as possible.

[ziyaozclk]

@cideM Imagine you have a middleware structure like the one below. You're adding to context RequestPath value.

 app.Use(func(c *fiber.Ctx) error {
	path := c.Path()
	if len(c.Request().URI().QueryString()) > 0 {
		path = c.Path() + "?" + string(c.Request().URI().QueryString())
	}
	c.Context().SetUserValue("RequestPath", path)

	err := c.Next()
        return err
 })

There are two ways RequestPath value is used in each logging process.

First way,

var fields []zap.Field

if ctxRequestPath, ok := c.Context().Value("RequestPath").(string); ok {
     fields = append(fields, zap.String("RequestPath", ctxRequestPath))
}

logger.Info("Static log message", fields...)

The second way, we don't have to pull RequestPath and other values from context as above everywhere. This gives us both code readability and performance.

logger.InfoCtx(c.Context(), "Static log message")

Performance Benchmark

Test	Time
ZapWithContext	2263 ns/op
Zap	2626 ns/op

[cideM]

@ziyaozclk thanks for the explanation and benchmarks, that's really great! There's something I don't understand though. In your commit, specifically in the test, you're doing reflection inside the Context function. And generateFields is called for every logger method, such as FatalCtx, and InfoCtx and so on. So every time someone calls one of those methods, reflection is used to turn context into zap fields.

If I now do the traditional thing and use zap.With that's not the case, right? To use your benchmark example...

 app.Use(func(c *fiber.Ctx) error {
	path := c.Path()
	if len(c.Request().URI().QueryString()) > 0 {
		path = c.Path() + "?" + string(c.Request().URI().QueryString())
	}

        // assuming the helper functions are defined somewhere in `logging`
        logger := logging.FromContext(c.Context())
        logger = logger.With(zap.String("RequestPath", path))
        c = logging.InjectLogger(logger)

	err := c.Next()
        return err
 })

this should only use reflection twice, once in this middleware to get the logger from context and once in the actual request handler to get the logger from context. But when we're doing the actual logging, so Infow, Debugw and so on, we just work with fields we already have.

Maybe I'm misreading and/or misunderstanding something here though. But I'd expect the zap.With benchmark to pull ahead the more logger methods are added to the benchmark.

[ziyaozclk]

@cideM You're right, I'm using reflection. But Reflection is also used in methods such as Infow and Debugw. I am not doing anything that will create an extra cost. Please correct me if I misunderstood. You create a new logger instance for each request in middleware. And you replace it with global logger instance. If we consider that your service is a service that responds to parallel requests, this will not work.

[cideM]

No global logger is involved, you get the logger that was previously injected into context, you modify that logger and re-insert it into context. Then handlers just get the modified logger from context and call logging methods. The usual thing.

Infow uses reflection, true, but your commit proposes the following signature InfoCtx(ctx context.Context, msg string, fields ...Field which requires Field to be passed in so I'm comparing it to Info not Infow.

The way I see it, using With and proper zap fields let's you call Info in handlers without additional reflection. Your commit adds reflection to every InfoCtx call without the convenience of being able to use keysAndValues ...interface{}.

Compare:

• logger.With(zap.String("RequestPath", path)) in middleware and Info in handler -> no reflection when logging, requires Field
• logging.Context(...) at app start and InfoCtx in handler -> reflection when logging, requires Field
• logger.With(zap.String("RequestPath", path)) in middleware and Infow in handler -> reflection when logging, can uses keysAndValues ...interface{}

One advantage of your approach is that it avoids the middleware for modifying the logger. You can configure the logger once at app start and pass it to your route handlers. No need to add the logger to context (which is quite common and for example zerolog/hlog even has helpers for it). I guess that this would make your solution faster in very specific cases where you only log once in a handler and with very few fields. Then you avoid the additional middleware cost but don't do much reflection. But that seems like a very narrow use case.

TL;DR: With + Info seems to be flexible and fast already and InfoCtx would add reflection overhead while sacrificing the convenience of keysAndValues ...interface{}.

Thanks for bearing with me so far 🙏🏻

[ziyaozclk]

Hi, I did benchmark tests for many options. I hope the following comparison is useful for you.

Operation	Time	Objects Allocated
ZapWithContextStaticMessage	3584 ns/op	34 allocs/op
ZapWithContextGenericMessage	3628 ns/op	34 allocs/op
ZapWithContextNoFields	3577 ns/op	34 allocs/op
ZapWithContextMultipleFields	3837 ns/op	39 allocs/op
ZapWithTraditionalMethodStaticMessage	4225 ns/op	44 allocs/op
ZapWithTraditionalMethodGenericMessage	4207 ns/op	44 allocs/op
ZapWithTraditionalMethodNoFields	4652 ns/op	44 allocs/op
ZapWithTraditionalMethodMultipleFields	4882 ns/op	49 allocs/op

NOT: ZapWithContext prefix is represent PR and ZapWithTraditional prefix is represent that only moves logger instance in context.

[chameleon82]

Instead of hardcoded Correlation-ID I would prefer just to pass context

  zap.L().Info("My log")

and traceable

 zap.L(ctx).Info("My log") 

to have that we just need to have

type Entry struct {
	Level      Level
	Time       time.Time
	LoggerName string
	Message    string
	Caller     EntryCaller
	Stack      string
        Context    *context.Context         <-- New field
}

so now I can create traceable ctx with traceID,spanID and other necessary information. Then I can create my own Core to export that data (simple wrapper over existing Cores or OpentelemetryOTLPCore) which will turn logs into OTLP log format and export with middleware.

[jalaziz]

Not to just be another comment, but this would be incredibly helpful. Having the context available to Core's and Hooks would greatly simply integrations like otel or sentry.

Without having the context passed through, we have to resort to all kinds of nasty workarounds (e.g. SkipType fields) and/or wrappers to ensure the context is passed through.

Also, as can be seen with zerolog and slog, having context-enabled log methods has started to become a standard that Zap is sorely missing.