Different tests log different results

[madkins23]

I started writing a set of tests to compare the output from the zerolog handlers I was testing. I wanted to make sure that the different tests were providing the same logging output. I found some things that seemed odd so I expanded that test to all of the other handlers as well.

1. I'm finding that some of the weak and accumulated tests are writing log entries with duplicate JSON fields.

Apparently for some tests the same fields are being configured as "context" as well as data. When the BenchmarkEventCtxWeak test runs it generates a handler via newWithCtx() which configures the handler with the various test fields. Then the same data is added again via logEventCtxWeak(). The result is that some handlers duplicate those fields in the output:

zerolog:   no
phuslog:  yes
zap:      yes
zapsugar: yes
slog:     yes
slogzap:  yes
apex:      no
logrus:    no
log15:     no
logf:     yes

I'm not sure if adding the same fields via context and logging is intentional. In any event, some tests are writing twice as much text for half of the tests.

2. Most of the handlers use "msg" for the message field name but a few use "message". The log/slog documentation shows a constant MessageKey = "msg" so it is probably a bug in the handler code for the apex, logf, phuslog, and zerolog handlers.

3. The phuslog handler fails JSON unmarshaling for several reasons:

• The handler inserts the "users" array of user objects as a string representation.
• The second occurrence of the "primes" field (see point 1 above) is likewise turned into a string.
• The second occurrence of the user field fails to make an embedded hash object for the second instance of "user":

"user":,"name":"John Doe","age":23,"dob":"2000-09-09T00:00:00Z",

5. The apex logger wraps the attribute fields in an additional object named "fields". In addition to using "message" the time is called "timestamp" instead of the log/slog constant TimeKey = "time".

6. The log15 doesn't use the proper timestamp format (missing Z). The log level is specified as "lvl" instead of the log/slog constant LevelKey = "level".

7. The logf handler doesn't generate JSON.

Some of these errors suggest bugs in the handlers and I may post them with the appropriate developers. The one that prompted me to write this ticket is the duplicate fields (point 1 above). I'd like to know what is expected (duplicate fields or not) and if the context fields should be different from the attribute fields added later. I am working on adding log/slog handlers for zerolog and I'd like to get them right so that I can see the performance thereof.

I'd also like to know if these new tests are of interest. If so I can create an appropriate pull request after I iron out some of these errors.

[madkins23]

Having thought about this some more:

• Point 1 seems important. If some tests are dumping duplicate fields and some aren't it seems like testing is apples vs. oranges. Granted the data is going into a CPU-free black hole (so no I/O time) there is still some work being done packaging up the duplicate fields for JSON (or whatever). My feeling is that there should be a separate set of fields for "context" so that the overlapping field names go away.
• The rest of it feels like stuff that should go into some sort of verification suite for log/slog. I'm considering building a test suite for slog handlers in a different repository. One of the tests would be for overlapping fields. So that stuff isn't your problem and I'm only leaving it in the previous comment in case it is of interest.

[madkins23]

And then there's this: golang/go#59365

[ayoisaiah]

@madkins23 Thanks so much for investigating this! I'll get back to you as soon as I'm able to check your comments and reproduce the problem (hopefully in a day or two).

[madkins23]

Sounds good. No particular hurry on my part. I've digressed to building a test harness for log/slog handlers (not ready yet and still private).

You might want check out the working branch of my fork of your code. It's a mess and not PR-ready although the two new tests for phsym and samber seem to work (ignore galecore, that handler is still building against the experimental version of slog). I figured to move specific items to separate branches and submit clean PRs if/when I got to that point.

In particular, the log_output_test.go file was where I got a lot of my notes for this ticket. If you run that there are a lot of errors but also some warnings (beginning with >>> ) and actual log records. You might search the output for the word duplicate. Of course you may wish to do your own testing. Trust but verify ;-).

[madkins23]

I've constructed my own set of tests of slog.Handler options currently available. Since most of these are wrappers around pre-existing logging libraries (i.e. zap, zerolog, and logrus) they are also quite different in features. The variance between different options is pretty impressive.

I used your GitHub Actions workflow as a starting point and constructed
my own set of GitHub Pages. Different pages look at the available data (verification and benchmark tests) in different ways. There's a link at the bottom left to the repository if you care.

I'm leaving this issue open for the moment, but I've moved on and you can close whenever you want.