rs / zerolog

Zero Allocation JSON Logger
MIT License
10.41k stars 567 forks source link

[proposal] the verbose field for including extended info if a trace is enabled #465

Open hedhyw opened 2 years ago

hedhyw commented 2 years ago

So the idea is to simplify the following snippet:

if logger.Trace().Enabled() {
    // Detailed message.
    logger.Debug().Interface("msg", msg).Msg("got message")
} else {
    // Only ID.
    logger.Debug().Interface("msg", msg.ID).Msg("got message")
}

With a helper:

logger.Debug().Verbose("msg", msg, msg.ID).Msg("got message")
// If a trace is enabled then it will include a detailed message.
// Otherwise it will include only ID.

It is possible to create a custom helper for this, but the last can check only the global level because an event doesn't have a getter of log level.

gucki commented 1 year ago

I like the idea, but a more flexible syntax like this one would be even better:

logger.Info().Debug(
  logger.String("id", msg.id),
  logger.Interface("xyz", "I only show up if level = debug"),
).Trace(
  logger.Interface("msg", msg),
  logger.Interface("xyz", "I only show up if level = trace"),
).Msg("got message")

It would only log the most verbose level available for this event. So if log-level is:

joeycumines commented 1 year ago

Disclaimer: I'm just chiming in because it's interesting, I'm not a contributor here

Most solutions I can think of ~would~ might involve allocs, might not be a problem, might not be desirable?

Helper(s) as @hedhyw suggests wouldn't need additional allocations, but might require defining a whole bunch of methods on the Event type, which could increase the API surface enough to be untenable. One alternative might be a closure-based guard (allowing re-use of the existing methods, somewhat modelling the existing if ... else solution), though ~it means~ that may mean* allocating that closure. (*) After benchmarking, it seems very plausible that the compiler would be smart enough to avoid unecessary allocs.

@gucki I'm not sure how you're imagining your suggestion specifically, but it seems like it'd require passing in some sort of "modifier" to a method that models the conditional write. Seems like it might be more "intensive" (relatively speaking, here) than a single closure.

In terms of what might address most of those caveats, another solution might be to define something like type TraceEvent Event, adding a method like func (*Event) Trace() *TraceEvent (which just casts the pointer), and implementing for *TraceEvent all of the relevant methods of *Event, with the relevant guard (e.g. logger level >= trace level). Would also need another method, to go back to *Event, for chaining. That also significantly increases the API surface, however.

joeycumines commented 1 year ago

I've been fiddling with patterns to support this use case, in my own (admittedly silly) project - a "zero alloc" log wrapper, with a similar API to zerolog, and I've landed on something I like, though I'm beginning to suspect it's inferior to just using a closure that gets called if the logger is enabled, and just performing the logic using normal conditional statements.

The pattern below can also support @gucki's request for multiple variations of log verbosity, though it results in a significantly greater API surface. Example here, if anyone's interested (didn't want to spam this issue too much).

Within zerolog, a possible solution solution might look something like:

type ConditionalEvent interface {
    // Event casts the receiver back to an *Event
    Event() *Event
    Else() ConditionalEvent
    ElseIf(cond bool) ConditionalEvent

    // (various other ElseIf* methods)

    // Any performs [Event.Any] conditionally.
    Any(key string, val any) ConditionalEvent

    // (various other non-terminating aliases for the Event methods)

    // future additions are expected / dont implement this
    private()
}

with three implementations (or two, with three being necessary to support "else if"), vaguely like type enabledEvent Event, type disabledEvent Event, and type terminatedEvent Event. To get a ConditionalEvent you could call a method like If*, on the *Event, and it would be either an *enabledEvent or *disabledEvent.

Else would return either *enabledEvent (if was disabled) or *terminatedEvent, ElseIf* would return *terminatedEvent unless the receiver was disabled, in which case it would return the same as the equivalent If* method on the *Event type.

The following is an example from my implementation, not zerolog @hedhyw's use case could be addressed like:

log := func(logger *Logger[Event]) {
    user := struct {
        ID        int64
        Name      string
        Email     string
        CreatedAt time.Time
    }{123, "John Doe", "johndoe@example.com", time.Unix(0, 1676147419539212123).UTC()}

    logger.Info().
        IfTrace().
        Any("user", user).
        Else().
        Int64("user", user.ID).
        Builder().
        Log("user created")
}

log(infoLogger)
log(traceLogger)

//output:
//[info] logger=infoLogger user=123 msg=user created
//[info] logger=traceLogger user={123 John Doe johndoe@example.com 2023-02-11 20:30:19.539212123 +0000 UTC} msg=user created