stdlib slog handler for zerolog

[shettyh]

Hi,

Is there any plan to add slog handler implementation for Zerolog ?. If there are no ongoing efforts then i can raise the PR the same

Regards

[rs]

No plan at the moment. What would be the use-case?

[euskadi31]

To no longer depend directly on a log library?

[rs]

Isn't slog self sufficient?

[shettyh]

@rs thanks for the response, slog provides default implementation for Json and Text but those are not as performant as zerolog. So having the handler interface implemented for zerolog will help to migrate to slog and no longer need to depend on specific logging library in application code

[rs]

Let’s try it. The risk is that the difference in performance comes from the API model. Please make sure to bench it so we don’t make false promises :)

[phsym]

If I understood it correctly, slog is mostly a logging frontend with a pluggable backend through the slog.Handler interface and it provides 2 backend implementations (logfmt and json). The main use case I have in mind is to have libraries using slog as the logging frontend, and let applications using those libraries choose the backend implementation. Some applications will probably use slog directly with one of the default backends, but other applications may use a more advanced logging library like zerolog, and plug the proper slog backend in order to have a consistent log output.

[jba]

Slog author here. Thanks @shettyh for beating me here! Slog will be in go 1.21, so it makes sense to provide some integration with it. I was going to suggest a slog.Handler that writes to a zerolog logger. @phsym nails the use case: letting packages that use slog and ones that use zerolog produce consistent output.

[phsym]

There will be a performance cost anyway.

Benchmarking slog with a "no-op" backend vs zerolog shows that slog frontend already brings some overhead. But still it will be great to have a zerolog handler for the libraries which will use slog.

No-Op handler:

type DummyHandler struct{}

func (*DummyHandler) Enabled(context.Context, slog.Level) bool {
    return true
}
func (*DummyHandler) Handle(context.Context, slog.Record) error {
    return nil
}
func (h *DummyHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
    return h
}
func (h *DummyHandler) WithGroup(name string) slog.Handler {
    return h
}

Bench:

func BenchmarkDummy(b *testing.B) {
    ctx := context.Background()
    l := slog.New(&DummyHandler{})
    l = l.With("foo", "bar")
    b.ResetTimer()
    for i := 0; i < b.N; i++ {
        l.LogAttrs(ctx, slog.LevelInfo, "hello", slog.String("bar", "baz"))
    }
}

func BenchmarkZerolog(b *testing.B) {
    l := zerolog.New(io.Discard).Level(zerolog.DebugLevel).With().Timestamp().Logger()
    l = l.With().Str("foo", "bar").Logger()
    b.ResetTimer()
    for i := 0; i < b.N; i++ {
        l.Info().Str("bar", "baz").Msg("hello")
    }
}

Results:

BenchmarkDummy-4         1876441           657.7 ns/op         0 B/op          0 allocs/op
BenchmarkZerolog-4       4235698           284.3 ns/op         0 B/op          0 allocs/op

In this particular test scenario, slog handler is already 2 times slower while doing nothing in the backend. With a zerolog backend it will then be at least 3 times slower and we must add some time to perform the mapping from slog concepts to zerolog concepts (mapping levels, attributes, ...)

[seankhliao]

I took a stab at it here https://github.com/rs/zerolog/compare/master...seankhliao:zerolog:slog-support but i wouldn't be comfortable submitting this given how inefficient this it is, in particular the need to support nested groups where not all the members are known up front. I think at the very least it would need a way to clone an Event to allow for partial preformatting.

[shettyh]

I also tried to add the support for slog handler and i echo @seankhliao.. In the current state it will be very inefficient to add support mostly because of this structure in slog

slog.With("outerKey", "outerValue").WithGroup("NestedGroup").With("NestedKey", "NestedValue").
    .WithGroup("NestedLevel2").With("Level2Key", "Level2value").Info("log msg")

Because keys/values for the zerolog.dict is not known when the group is initialised, One way to solve this is to maintain nested chain of *zerolog.Event event, but currently there is no support cloning for *Event as mentioned in the above comment. Using zerolog.Context is also not feasible as to add nested structure we need to have *Event somewhere 😞

[phsym]

I gave it a try too, only using current public API. The ony way I found to have some kind of clonable *Event is to create and empty Context{} (here), write fields into it (here), the clone it into an *Event by calling Context.Log() (here) then propagate to the parent groupHandler which clones its own context, writes the child's event into it with Dict() , propagate the new event to the next parent, and so on until it reaches the root logger.

It works, but there are lot of useless buffer copies which will make it inefficient if there are multiple nested groups. But in practice, will there be that much nested groups ?

So I tried an other approach: add support for groups in zerolog itself --> https://github.com/rs/zerolog/compare/master...phsym:zerolog:slog-handler

Basically I added methods to Context and *Event:

• Group(name string): Opens a new group
• Grouped(name string, f func(E) E): Opens a group, calls f then close the group
• Ungroup(n int): Close one, many or all opened groups

I made those methods public so that my slog handler (in package zerolog/zslog) can call them, but alternatively if @rs prefers not to make them public (yet?) they could be made private if the handler is at the root of the module instead of a dedicated package (see https://github.com/rs/zerolog/compare/master...phsym:zerolog:slog-handler-private-groups). @rs any thought on this ?

Groups are automatically closed when sending an event, and they are closed before applying hooks, so that timestamps and callers are not added to a group.

[phsym]

Coming back to the big performance overhead brought by slog.Logger, I see 1 main reason for that:

• slog.Logger always calls runtime.Callers() event when the handler doesn't need the source info (here)

We can update my previous benchmark to measure that, by adding:

import _ "unsafe"

//go:linkname IgnorePC log/slog/internal.IgnorePC
var IgnorePC bool

func BenchmarkDummy_NoPC(b *testing.B) {
    IgnorePC = true
    b.Cleanup(func() {
        IgnorePC = false
    })
    BenchmarkDummy(b)
}

goos: darwin
goarch: amd64
pkg: github.com/phsym/zeroslog/bench
cpu: Intel(R) Core(TM) i5-1038NG7 CPU @ 2.00GHz
BenchmarkDummy-8             1388012           775.5 ns/op         0 B/op          0 allocs/op
BenchmarkDummy_NoPC-8        6785779           187.6 ns/op         0 B/op          0 allocs/op
BenchmarkZerolog-8           2959240           406.3 ns/op         0 B/op          0 allocs/op

There is still some overhead, but much less.

I've ran this bench on a different laptop than previously, so numbers have changed a bit, but what is important is the delta between BenchmarkDummy-8 and BenchmarkDummy_NoPC-8

I don't know if there are plans already to update slog so that it's not calling runtime.Callers() when it's not needed (maybe @jba has some insight on this).

In the meantime, logging with slog in performance critical code should probably be done by calling the handler directly which has very few overhead

if hdl := logger.Handler(); hdl.Enabled(ctx, lvl) {
    rec := slog.NewRecord(time.Now(), lvl, msg, 0)
    rec.AddAttrs(attrs...)
    hdl.Handle(ctx, rec)
}

[jba]

We talked a lot about whether that runtime.Callers call should always happen. As you can see from that internal symbol, I also benchmarked it and I also found it significant, compared to not doing it. But since we were able to match Zap performance even with the call, we did not add any API to disable it.

That is still my feeling: it is not a goal to match zerolog performance, so I don't think slog should add API to try. Of course, other approaches are welcome, like calling the hander directly (which you can wrap in a nice function) or some possible future work on speeding up runtime.Callers by doing more at compile time.

[mitar]

@jba: From what I see, it might be a missed opportunity for Handler interface to have Caller method. With Caller method, handlers could determine themselves if and how to obtain the caller.

[mitar]

I looked briefly at this and I have few thoughts:

• For Enabled method, there is currently private Logger.should. Probably Handler.Enabled should just call into it?
  • Do note that I am proposing to add Logger.Enabled in https://github.com/rs/zerolog/pull/617 with a different signature which matches Event.Enabled.
• It seems the only tricky thing is WithGroups and I had the same idea than @phsym: groups can be made already into a prefix buffer, the same as .With does, only that you have to append few } at the end.
• Do we want to support full slog.HandlerOptions? Or only the AddSource and Level subset?

So I think work made by @phsym is the way to go. @rs: We should just decide if you want Group and related feature to be public or private?

[jba]

It seems the only tricky thing is WithGroups and I had the same idea than @phsym: groups can be made already into a prefix buffer, the same as .With does, only that you have to append few } at the end.

I haven't been following the implementation here, so I may be confused, but if you preformat attrs then you have to deal with groups too. For slog calls like

logger.With("a", 1).WithGroup("g").With("b", 2)

the preformatted data must be something like

{"a": 1, "g": {"b": 2},

[mitar]

@jba Exactly! This is what @phsym implementation does. It just maintains a stack of buffers which combine both attrs and groups as a prefix. You then prepend that as necessary and add } as necessary. I think that is reasonably performant. The question is only if this whole grouping feature should be public or private. I think public would be better because it would be sad that people would have to use slog just to get a feature from zerolog which it internally implements but does not expose.

[madkins23]

Benchmark and verification testing of available slog.Handler wrappers around various logging libraries. The @phsym wrapper is coming in as fastest, the slog/JSONHandler implementation seems the most feature complete.

Given the speed of zeroslog with the phsym/zeroslog wrapper around it, I can't help wondering about a V2 version of rs/zerolog that was slog-compliant and feature complete (for some definition thereof).

[mitar]

I do not think V2 of rs/zerolog is necessary here. slog can be supported in backwards compatible way. Only @rs should way in if it is OK for the approach by @phsym to be made into a PR. The question is if group feature should be public or private. I think if it is implemented, there is little reason not to make it public.

[rs]

Agreed, I would prefer to avoid a V2.

[mitar]

@rs: Are you OK with adding public Group feature to zerolog?

[madkins23]

I'm sorry to have raised anyone's blood pressure by mentioned V2. I understand the push back.

What I was trying to suggest is that a zerolog.Logger might evolve into a slog.Handler by implementing that interface. My thought was that it might be possible to optimize logging speed by "keeping it all in-house" as it were, as opposed to writing a slog.Handler wrapper around a zerolog.Logger.

My first concern was that it might not be possible to implement slog.Handler without breaking some existing code. The four methods in the slog.Handler interface don't seem to exist on zerolog.Handler at the current time so that should not be an issue creating new methods to suit. On the other hand there may be a conceptual mismatch that makes this difficult to do without breaking existing code.

My second concern is that there is a lot of feature mismatch among the various logging libraries that are currently being wrapped by slog.Handler objects. Things like whether a group named with the empty string is kept as is or inserted inline into the parent group or log record or what field name is used for the log message. You can look at a typical list of such discrepancies for phsym/zeroslog here (at the bottom of the page below the charts).[^1]

A lot of the warnings I have defined after doing a lot of testing against all of the slog JSON implementations I know about are pretty picky and likely don't matter. On the other hand, some of them (which I mark as Required) are pretty much specified in existing slog.Handler documentation. Coming close to what the slog.JSONHandler implementation does might require changing how zerolog outputs logs which could lead to a (gasp) V2 version (oh, noes!).

But that's all just something I was considering as opposed to making changes that would be intended to support outside slog.Handler wrappers. My apologies for any upset and I'll shut up about it now.

[^1]: As a side note, looking at the charts on the bench test pages (for example: logging a big nested group) shows phsym/zeroslog beating the competition. So kudos to rs/zerolog and phsym/zerolog!

[mitar]

@madkins23 Thank you for all this great work doing all that comparison and analysis. But I am not completely sure if zerolog slog implementation should behave exactly like slog.JSONHandler? I do not think JSONHandler is normative for all JSON slog implementations. I think some differences should be expected?

[madkins23]

Absolutely. I used slog.JSONHandler behavior as definitive for some of the lower level warnings because, well, it's there and it's part of the basic kit.

The use case in my mind when I started generating the benchmark and verification data was replacing one handler with another in an existing system. I figure the system is likely logging JSON because there are downstream processes reading the logs. How does the system architect determine which handlers will have the best performance as well as the least incompatible change in JSON output? How do software engineers prepare for any changes in the downstream processes?

I have no expectation that any given logger library such as zerolog should behave according to any specific standard. The authors of slog.Handler wrappers such as phsym/zeroslog might choose to use the data as room for improvement where the changes will be backward compatible or the wrapper is still in pre-release.

[jba]

whether a group named with the empty string is kept as is or inserted inline into the parent group

Groups named with the empty string should be inserted inline.

Whether or not you conform to this and other handler specifications, I recommend using testing/slogtest to check your handlers. If you use the Run function, you can opt out of individual behaviors with t.Skip. If all handlers do that, then you will have a clear, enforced list of their discrepancies with "official" slog and with each other.

Ideally, all handlers would behave the same. Often that is impossible for compatibility or implementation reasons. But if your handler violates the spec just because you think the alternative is valuable (like outputting empty groups, for example), then I suggest making the choice an option, with the default being the official behavior. Users will benefit by having a more uniform experience across handlers.

[madkins23]

TL;DR Agreed, plus another shameless plug for my own slog test harness.

Four out of the six handlers I'm testing fail that particular test (use the Log buttons to see the actual output).

My test harness includes tests inspired by slog documentation, slogtest, tests embedded in betterstack-community/go-logging-benchmarks, and a few I just made up. The only test harness that "passes" virtually all of them is slog/JSONHandler.

That doesn't mean my tests are authoritative, but I've tried to link each of them (and each of the "warnings" I generate) to some supporting documentation where possible. In this particular case I link to "- If a group's key is empty, inline the group's Attrs." in the documentation for slog.Handler.

[wangkang]

https://github.com/struqt/logging/blob/main/logging.go

package logging

import (
    "io"
    "log/slog"
    "os"
    "sync"
    "time"

    "github.com/go-logr/logr"
    "github.com/go-logr/zerologr"
    "github.com/rs/zerolog"
    "gopkg.in/natefinch/lumberjack.v2"
)

var setupOnce sync.Once

func setup() {
    setupOnce.Do(func() {
        zerologr.NameSeparator = "/"
        zerologr.NameFieldName = "N"
        zerologr.VerbosityFieldName = "V"
        zerologr.SetMaxV(LogVerbosity)
    })
}

var (
    LogRotateMBytes     uint16 = 16
    LogRotateFiles      uint16 = 64
    LogVerbosity               = 2
    LogConsoleThreshold        = int8(zerolog.TraceLevel)
    DefaultLogger              = NewLogger("")
)

func NewLogger(path string) *slog.Logger {
    logger := NewLogr(path)
    sLogger := slog.New(logr.ToSlogHandler(logger))
    return sLogger
}

func NewLogr(path string) logr.Logger {
    setup()
    console := NewThresholdConsole()
    var logger *zerolog.Logger
    if len(path) > 0 {
        verbose := NewLumberjack(LogRotateMBytes, LogRotateFiles, path)
        logger = NewZerolog(verbose, console)
    } else {
        logger = NewZerolog(console)
    }
    return zerologr.New(logger)
}

func NewLumberjack(fileMBytes uint16, fileCount uint16, path string) *lumberjack.Logger {
    logger := &lumberjack.Logger{
        Filename:   path,
        MaxSize:    int(fileMBytes),
        MaxBackups: int(fileCount),
        LocalTime:  false,
        Compress:   true,
    }
    return logger
}

func NewZerolog(writers ...io.Writer) *zerolog.Logger {
    multi := zerolog.MultiLevelWriter(writers...)
    logger := zerolog.New(multi).With().Timestamp().Caller().Logger()
    return &logger
}

type ThresholdWriter struct {
    threshold zerolog.Level
    writer    zerolog.LevelWriter
}

func (t *ThresholdWriter) Write(bytes []byte) (n int, err error) {
    return t.WriteLevel(zerolog.NoLevel, bytes)
}

func (t *ThresholdWriter) WriteLevel(level zerolog.Level, bytes []byte) (n int, err error) {
    if level >= t.threshold {
        return t.writer.WriteLevel(level, bytes)
    }
    return len(bytes), nil
}

func NewThresholdConsole() *ThresholdWriter {
    console := zerolog.ConsoleWriter{
        Out:        os.Stderr,
        TimeFormat: time.RFC3339,
    }
    return &ThresholdWriter{
        writer:    zerolog.MultiLevelWriter(console),
        threshold: zerolog.Level(LogConsoleThreshold),
    }
}

[phuslu]

Hi phuslog author here, I recognized that implemented full support to slog group is not easy as @shettyh described. Finally I managed to implement it by 3 recursive functions(with minimal memory allocs). See

https://github.com/phuslu/log/blob/master/logger_std_slog.go

Maybe this have tips or hints for zerolog.

[phuslu]

Based on above basis, I developed a drop-in slog.JSONHandler replacement in https://github.com/phuslu/log/blob/master/slog.go

It's fast and 0-allocs, and passed all tests in slogtest.

[trim21]

I write a immature implement using zerolog as slog.Handler. it pass most of slogtest except multi-With (nested group）

https://github.com/trim21/zerolog-as-slog-handler

group design of slog doesn't fit zerolog very well