Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging with context values #1019

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

ziyaozclk
Copy link

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
Copy link

CLAassistant commented Oct 8, 2021

CLA assistant check
All committers have signed the CLA.

logger.go Outdated Show resolved Hide resolved
@polanskya
Copy link

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

@ziyaozclk ziyaozclk force-pushed the logging_with_context branch 2 times, most recently from 2d76282 to 0e5b37a Compare November 30, 2021 06:21
@ziyaozclk ziyaozclk force-pushed the logging_with_context branch 2 times, most recently from d66040c to f8ea1ae Compare March 10, 2022 19:27
@cideM
Copy link

cideM commented Mar 11, 2022

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
Copy link
Author

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
Copy link

cideM commented Mar 14, 2022

@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
Copy link
Author

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

@ziyaozclk
Copy link
Author

ziyaozclk commented Mar 17, 2022

@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
Copy link

cideM commented Mar 18, 2022

@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
Copy link
Author

@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
Copy link

cideM commented Mar 20, 2022

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
Copy link
Author

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
Copy link

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
Copy link

jalaziz commented Oct 7, 2023

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

7 participants