Native log broken for package consumers

[synthmeat]

v1.13.6 introduced issue where it breaks log usage for package consumers.

$ go version
go version go1.21.5 darwin/arm64

Minimal code to reproduce, where expectation is to print anything to stderr. What happens is that it doesn't print anything at all. (fmt to either stdout or stderr works fine.)

main.go

package main

import (
        "log"

        "github.com/ethereum/go-ethereum/ethclient"
)

func main() {
        log.Println("shalala")
        _, err := ethclient.Dial("https://cloudflare-eth.com")
        if err != nil {
                log.Println(err)
        }
        log.Println("shalala")
}

go.mod

module gethrepro

go 1.21

require github.com/ethereum/go-ethereum v1.13.6

require (
        github.com/Microsoft/go-winio v0.6.1 // indirect
        github.com/StackExchange/wmi v1.2.1 // indirect
        github.com/bits-and-blooms/bitset v1.10.0 // indirect
        github.com/btcsuite/btcd/btcec/v2 v2.2.0 // indirect
        github.com/consensys/bavard v0.1.13 // indirect
        github.com/consensys/gnark-crypto v0.12.1 // indirect
        github.com/crate-crypto/go-kzg-4844 v0.7.0 // indirect
        github.com/deckarep/golang-set/v2 v2.1.0 // indirect
        github.com/decred/dcrd/dcrec/secp256k1/v4 v4.0.1 // indirect
        github.com/ethereum/c-kzg-4844 v0.4.0 // indirect
        github.com/go-ole/go-ole v1.2.5 // indirect
        github.com/gorilla/websocket v1.4.2 // indirect
        github.com/holiman/uint256 v1.2.4 // indirect
        github.com/mmcloughlin/addchain v0.4.0 // indirect
        github.com/shirou/gopsutil v3.21.4-0.20210419000835-c7a38de76ee5+incompatible // indirect
        github.com/supranational/blst v0.3.11 // indirect
        github.com/tklauser/go-sysconf v0.3.12 // indirect
        github.com/tklauser/numcpus v0.6.1 // indirect
        golang.org/x/crypto v0.15.0 // indirect
        golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa // indirect
        golang.org/x/mod v0.14.0 // indirect
        golang.org/x/sync v0.5.0 // indirect
        golang.org/x/sys v0.14.0 // indirect
        golang.org/x/tools v0.15.0 // indirect
        rsc.io/tmplfunc v0.0.3 // indirect
)

[0x0elliot]

I would like to fix this. I could reproduce this bug. Can someone give me some context about this issue? :)
I am new to the geth ecosystem, and would like to contribute. This seems like a simple entrypoint!

[namiloh]

Figuring out what happened and why is the large part of fixing any bug (mostly). Go for it, @0x0elliot !

[0x0elliot]

I will then! Let me get done with another PR I am working on and get to this. Kindly assign :)

[0x0elliot]

This seems like intended behaviour @synthmeat

https://github.com/ethereum/go-ethereum/releases/tag/v1.13.6 in here it clearly states:

In the absence of an 'official' Go logging framework, go-ethereum has, for a very long time, used a custom in-house logger. However, just such an 'official' Go logging framework has now arrived, with the [slog](https://go.dev/blog/slog) package.

and...

@namiloh This seems intended. Is there still some optimisation you would want me to make to help out users?

[synthmeat]

@0x0elliot But I'm clearly not using github.com/ethereum/go-ethereum/log, I'm using log from the Go's standard library. How is breaking stdlib "intended"?

[0x0elliot]

@synthmeat Right! I missed that. Let me look deeper.

[0x0elliot]

Interesting observation:

package main

import (
	"log/slog"
	"os"
	"fmt"
	"github.com/ethereum/go-ethereum/ethclient"
	"github.com/ethereum/go-ethereum/log"
)

func main() {
	_, err := ethclient.Dial("https://mainnet.infura.io")
	if err != nil {
		fmt.Println("error")
	}

	slog.Info("(1) hello world")
	log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelInfo, true))) // recommendation made
	slog.Info("(2) hello world")
}

That's extremely interesting. It is happening because of:

go-ethereum/log/root.go

Line 13 in 28e7371

defaultLogger := &logger{slog.New(DiscardHandler())}

where init() is called.

Same observation is made when I just import "github.com/ethereum/go-ethereum/log" into the code:

package main

import (
	"log/slog"
	"os"
	// "github.com/ethereum/go-ethereum/ethclient"
	"github.com/ethereum/go-ethereum/log"
)

func main() {
	slog.Info("(1) hello world")
	log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelInfo, true)))
	slog.Info("(2) hello world")
}

[0x0elliot]

To summarise it @synthmeat, Technically, you're not using "github.com/ethereum/go-ethereum/log" but ethereum's ethclient uses it.

@namiloh since this is "intended behaviour", I guess, I can update documentation for it (just by this issue existing as well, Life becomes easy for those trying to figure out what's making their logs disappear)

More here: #28558 (comment)

but the logs would silently disappear as we're be pushing them into an uninitialized slog

[namiloh]

This behaviour seems wrong to me, I don't see why we should initiate slog with a default discard-handler. We could just leave it be whatever it already is.
Not sure. As it is, we force the 'main' to explicitly configure it, otherwise logs are discarded. It is a bit naughty behaviour for a library to do that, even though arguable the 'main' ought to configure it.

[fjl]

This issue is about package log and not package log/slog. We need to make sure that our initialization of slog does not automatically redirect messages printed with package log.

[namiloh]

I assume golang authors decided to route log to slog...?

[0x0elliot]

i went ahead and used slog (and forgot to remove it while experimenting around) because log and slog show similar behaviour in this context!

[fjl]

The issue happens because we call slog.SetDefault from an init function. This will override the default output of package log. I think we can remove this init function.

[0x0elliot]

@fjl where will this overriding be done then next, if we would still need to do that? (i can figure this on my own soon enough when i am on keyboard)