Migrate from zerolog to slog

[dgduncan]

This PR, if approved, will be merged upon the release of GO v1.21.

This PR changes the repository over from zerolog to slog. Some important considerations were taken when working on this PR:

• zerolog is capable of low to zero allocation logging. Because of this, I decided to use LogAttrs to get as close to this performance as possible at the expense of readability.
• slog does not have any equivalent to .Err() where you can pass an error directly to and it will check if nil in .Err() itself. To get around this, an if has been included on those calls and the log lines all but duplicated. I would love some feedback and see if anyone has any other ideas for this.

[coveralls]

Pull Request Test Coverage Report for Build 5379673535

• 437 of 482 (90.66%) changed or added relevant lines in 14 files are covered.
• 11 unchanged lines in 4 files lost coverage.
• Overall coverage decreased (-0.5%) to 98.105%

---

Changes Missing Coverage	Covered Lines	Changed/Added Lines	%
listeners/websocket.go	1	2	50.0%
hooks/storage/badger/badger.go	101	105	96.19%
hooks/storage/bolt/bolt.go	90	94	95.74%
server.go	65	73	89.04%
hooks/storage/redis/redis.go	108	136	79.41%

Files with Coverage Reduction	New Missed Lines	%
hooks/storage/badger/badger.go	1	95.78%
hooks/storage/bolt/bolt.go	1	98.7%
server.go	2	99.07%
hooks/storage/redis/redis.go	7	92.24%

Totals
Change from base Build 5310181217:	-0.5%
Covered Lines:	5487
Relevant Lines:	5593

---

💛 - Coveralls

[dgduncan]

I am a bit confused about coveralls does their line calculation. How could there be a 0.5% change when lines were only replaced?

[dgduncan]

I have removed the Delay Merging tag in the name as I believe now with the release of GO 1.21 we can move forward.

[torntrousers]

Big change to review but LGTM. Will this go in with a Mochi minor version update as some indication people need to also update Go in ther environment?

[dgduncan]

@torntrousers I believe. I was also thinking if there was any apatite for some more experimental version tag to denote that this is a big change and a way to test before having it in an official version release; however, I don't want to start muddying up our versions.

[werbenhu]

I've reviewed the changes, and everything looks fine. LGTM. I looked into slog, and it doesn't directly support interface-based abstraction. Perhaps we can make it more flexible by creating an adapter to achieve a similar interface-like behavior. This interface could include common log functions such as Info(), Infof(), Error(), Errorf(), etc. We could provide a default logger implementation using slog, and users could switch to other loggers by implementing their own logger structs and swapping them in the Server code. @mochi-co @dgduncan, I'd like to hear your thoughts on this approach.

[dgduncan]

@werbenhu If I understand what you mean correctly, I personally feel that providing a Logger type interface that can be interchanged is of lower importance than moving more towards using the standard library. If there is an expressed interest by users for that functionality we can work to implement.

[werbenhu]

@dgduncan I've written a simple stress test to compare the performance differences between slog.LogAttrs(), slog.Info(), and zerolog.Info(). Below is my code and the results:

package main

import (
	"context"
	"os"
	"testing"

	"github.com/rs/zerolog"
	"golang.org/x/exp/slog"
)

func BenchmarkSlogInfo(b *testing.B) {
	f, err := os.OpenFile("a.txt", os.O_CREATE|os.O_WRONLY|os.O_TRUNC, 0600)
	if err != nil {
		panic(err)
	}
	defer f.Close()

	log := slog.New(slog.NewTextHandler(f, nil))
	b.ResetTimer()
	for n := 0; n < b.N; n++ {
		log.Info("hello world", "index", n, "name", "werben", "age", 300)
	}
}

func BenchmarkSlogAttr(b *testing.B) {
	f, err := os.OpenFile("b.txt", os.O_CREATE|os.O_WRONLY|os.O_TRUNC, 0600)
	if err != nil {
		panic(err)
	}
	defer f.Close()

	log := slog.New(slog.NewTextHandler(f, nil))
	b.ResetTimer()
	ctx := context.TODO()
	for n := 0; n < b.N; n++ {
		log.LogAttrs(ctx,
			slog.LevelInfo,
			"hello world",
			slog.Int("index", n),
			slog.String("name", "werben"),
			slog.Int("age", 300),
		)
	}
}

func BenchmarkZerologInfo(b *testing.B) {
	f, err := os.OpenFile("c.txt", os.O_CREATE|os.O_WRONLY|os.O_TRUNC, 0600)
	if err != nil {
		panic(err)
	}
	defer f.Close()

	zlog := zerolog.New(os.Stderr).Output(zerolog.ConsoleWriter{Out: f})
	b.ResetTimer()

	for n := 0; n < b.N; n++ {
		zlog.Info().
			Int("index", n).
			Str("name", "werben").
			Int("age", 300).
			Msg("hello world")
	}
}

cpu: Intel(R) Core(TM) i5-7400 CPU @ 3.00GHz
BenchmarkSlogInfo-4                95996             11695 ns/op               7 B/op          0 allocs/op
BenchmarkSlogAttr-4               103012             10719 ns/op               0 B/op          0 allocs/op
BenchmarkZerologInfo-4             61846             17071 ns/op            2169 B/op         65 allocs/op

From my results, slog outperforms zerolog by a significant margin. However, the difference between slog.LogAttrs() and slog.Info() is not very significant. Personally, I lean towards the style of log.Info(), which is concise and elegant. I'm unsure about how others perceive this code style. If the majority share my perspective, could we consider sacrificing a slight amount of performance for code that is more elegant?

[mochi-co]

I'm just moving house this week so I'm a bit short on connectivity, but I'm going to reply to all these shortly - it's great work you've done!

[dgduncan]

@werbenhu Wow thank you so much for doing that test and putting some numbers to what I have read. I absolutely am in favor of a more elegant and easier to read Info compared to LogAttrs if the performance is indeed this close.

[coveralls]

Pull Request Test Coverage Report for Build 6034299854

• 161 of 173 (93.06%) changed or added relevant lines in 14 files are covered.
• No unchanged relevant lines lost coverage.
• Overall coverage decreased (-0.005%) to 98.874%

---

Changes Missing Coverage	Covered Lines	Changed/Added Lines	%
hooks/storage/badger/badger.go	31	32	96.88%
hooks/storage/bolt/bolt.go	26	27	96.3%
listeners/websocket.go	1	2	50.0%
server.go	24	26	92.31%
hooks/storage/redis/redis.go	37	44	84.09%

Totals
Change from base Build 5840455576:	-0.005%
Covered Lines:	5268
Relevant Lines:	5328

---

💛 - Coveralls

[dgduncan]

I made another update as per the mention of @thedevop of changingerr.Error() to just err

[dgduncan]

So I have decided to leave the log.Fatal(err) as these are technically just examples of how the server can be used and is left up to the user to change the way they want to exit the application.

Unless anyone has any other objections I do believe that this is ready for final review by @mochi-co .

[mochi-co]

So much good stuff in this PR, thank you @dgduncan, @werbenhu, @thedevop, @torntrousers. Particularly great to see the benchmarks, helps in making an informed decision. Apologies for being late to the party.

Overall I think this is the right move and I'm excited to get it merged in. My thoughts:

• Where log.Fatal has been used, we should keep it as-is. Generally this clearly indicates the end-of-the-road for the runtime and its meaning is unmistakable.
• Prefer shorthand convenience functions Info, Error, etc. over LogAttrs - the difference in performance is negligible compared to other costs which could be optimised (topics, for example).
• Since the beginning, this project has gone from single embedded logger, to logging interface, back to single embedded logger. In my anecdotal experience, nobody ever reimplemented the built-in logger, so we moved to zerolog directly. I would wager that many packages will migrate towards log/slog over the next year to avoid this 'which logger' problem, and as adoption increases, the output format of log/slog will become common-place and expected. For this reason, I am inclined to suggest remaining with direct log/slog calls for now - if there's a serious demand for a logging interface, we should implement it as a new feature.
• log/slog imports should be at the top of the imports block ;)
• I miss the terminal colours from zerolog.

However, in conclusion I am very excited about this change. @dgduncan you have done a superb job at driving this project forward, and implementing it in a thoughtful and well-considered way. I think this is something you can be proud of.

[mochi-co]

I've reviewed this PR, the only recommendation I have is to remove the 48 calls to errorMsg.Error() - as @thedevop noted, this is no longer needed when using log/slog. Otherwise, looks good to me!

[mochi-co]

Approved. I'll leave it for a bit for anyone to raise any other concerns, otherwise I will merge this in over the weekend and release as v2.4.0!

[thedevop]

@dgduncan , as I prepare my application for this break change (as I do override default logger), I ran into few issues, maybe you have some insights to simple solutions:

1. slog with JSONHandler can't log struct unless it implements LogValuer or json.Marshaler. I can do this for my own struct, but can't really do that for 3rd party struct. Using TextHandler works as struct->string is built-in.
2. if the object is already in json, slog can't just add the raw json without adding all the escape character to treat it as one long string. Found a way by wrapping it.

[dgduncan]

@thedevop Would you mind explaining providing an example of a struct that is failing to be logged? I have not run into this issue yet in my own use. Do you mean that there is something struct that is attempting to be logged and there is something inside said struct that fails which breaks the record or shows a BadKey because it does not implement either interface?

[mochi-co]

I want to see what @thedevop says before I merge this in case there's a compelling reason that we really should be adding an interface.

[dgduncan]

@mochi-co I am curious as well. I do think that if this is a problem in only very specific use cases you in theory should be able to wrap the struct in another struct that implements LogValue and when reflect over that struct that is causing problems if you wanted to mirror that struct to log or build the json.RawMessage map by manually going over that struct that is causing the problem.

The thing I do want to know is if this is a problem for structs that are being logged in the broker code itself or if this is a problem with code from in the embedding application that will now have to use slog with this change. Because the first is breaking the broker itself and the other is a implementation challenge of moving to a new standard.

[thedevop]

This is a problem for any struct that doesn't implement LogValuer (or json. Marshaler) interface AND using JSONHandler.

Here is an example that demonstrates the issue: https://go.dev/play/p/KNsC_CmrmSG. I also have B which implements LogValue (commented out).

type A struct {
	name  string
	value int
}
	textLog := slog.New(slog.NewTextHandler(os.Stdout, nil))
	jsonLog := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	a := A{"test", 123}
	textLog.Info("text without logvalue", "a", a)
	jsonLog.Info("json without logvalue", "a", a)

shows up empty with JSONHandler for a:

time=2009-11-10T23:00:00.000Z level=INFO msg="text without logvalue" a="{name:test value:123}"
{"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"json without logvalue","a":{}}

[werbenhu]

@thedevop the JSON marshaling process only formats the fields that are exported. Making Name and Value of struct A exported is fine. https://go.dev/play/p/8H4doeulXIS

package main

import (
	"log/slog"
	"os"
)

type A struct {
	Name  string
	Value int
}

func main() {
	textLog := slog.New(slog.NewTextHandler(os.Stdout, nil))
	jsonLog := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	a := A{"test", 123}
	textLog.Info("text without logvalue", "a", a)
	jsonLog.Info("json without logvalue", "a", a)
}

// Output:
// time=2009-11-10T23:00:00.000Z level=INFO msg="text without logvalue" a="{Name:test Value:123}"
// {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"json without logvalue","a":{"Name":"test","Value":123}}

[thedevop]

@werbenhu , you're right! I missed that because the TextHandler was able log. Thanks!

[mochi-co]

If everyone is happy, I will merge this branch. Please let me know 🙂

[dgduncan]

What Hath God Wrought. - Samuel Morse
It is possible to commit no mistakes and still lose. - Jean-Luc Picard

Engage.

[mochi-co]

Merged! Amazing, immense work by everyone, especially @dgduncan! 🥳
This will probably go out between now and the weekend as a new minor version 2.4.0 🙂