internal/debug: add switch to format logs with json

[s1na]

This PR adds a switch --logjson which if enabled makes the client format logs with JSON.

Something I'm not clear about is if setting glogger needs to be done in init. I had to move it to Setup to have access to the flags. Could this have an unintended consequence?

Fixes #21926

[holiman]

Something I'm not clear about is if setting glogger needs to be done in init. I had to move it to Setup to have access to the flags. Could this have an unintended consequence?

It doesn't need to be done in init, it's just that init is called very very early. And we want to configure the logger very early, since someting may need to log something in a very early phase.

On a normal run, this seems to work fine (as in, nothing in the normal case tries to log anything before we have performed Setup):

 ./build/bin/geth --logjson --nodiscover --maxpeers 0  
{"lvl":"info","msg":"Starting Geth on Ethereum mainnet...","t":"2021-01-25T14:32:25.359673574+01:00"}
{"lvl":"info","msg":"Bumping default cache on mainnet","provided":1024,"t":"2021-01-25T14:32:25.359768424+01:00","updated":4096}
{"lvl":"warn","msg":"Sanitizing cache to Go's GC limits","provided":4096,"t":"2021-01-25T14:32:25.35985691+01:00","updated":2589}

I'll test it a bit more to see if I can find any place where geth tries to log before we've called Setup

[holiman]

I had to move it to Setup to have access to the flags. Could this have an unintended consequence?

Oh, yeah there's one more thing aswell: there's this glogger global variable, which is nil until Setup is called -- whereas init would initialize it during class loading (or whatever the go-idiomatic word for that is) . I don't see it as a problem, however, because it's only accessed via debug.Verbosity, debug.VModule and debug.BackTraceAt RPC calls, and the RPC stack isn't spun up until much later.

[holiman]

I think you can combine the two, and make it even better than it is on master. On master, if something logs before we've called Setup, it won't actually be printed.

[user@work go-ethereum]$ git diff

diff --git a/internal/debug/flags.go b/internal/debug/flags.go
index a39a4a3194..92a46d3e8e 100644
--- a/internal/debug/flags.go
+++ b/internal/debug/flags.go
@@ -130,9 +130,16 @@ var DeprecatedFlags = []cli.Flag{
 
 var glogger *log.GlogHandler
 
+func init() {
+       glogger = log.NewGlogHandler(log.StreamHandler(os.Stderr, log.TerminalFormat(false)))
+       glogger.Verbosity(log.LvlInfo)
+       log.Root().SetHandler(glogger)
+}
+
 // Setup initializes profiling and logging based on the CLI flags.
 // It should be called as early as possible in the program.
 func Setup(ctx *cli.Context) error {
+       log.Info("setting up logging")
        var ostream log.Handler
        output := io.Writer(os.Stderr)
        if ctx.GlobalBool(logjsonFlag.Name) {
@@ -144,8 +151,7 @@ func Setup(ctx *cli.Context) error {
                }
                ostream = log.StreamHandler(output, log.TerminalFormat(usecolor))
        }
-       glogger := log.NewGlogHandler(ostream)
-
+       glogger.SetHandler(ostream)
        // logging
        log.PrintOrigins(ctx.GlobalBool(debugFlag.Name))
        glogger.Verbosity(log.Lvl(ctx.GlobalInt(verbosityFlag.Name)))

Running this, which contains an extra logging before we've actually set up the desired logging, yields:

[user@work go-ethereum]$ ./build/bin/geth --logjson --nodiscover --maxpeers 0 --config=/bax/noz
INFO [01-25|14:49:57.978] setting up logging 
{"lvl":"info","msg":"Starting Geth on Ethereum mainnet...","t":"2021-01-25T14:49:57.978621371+01:00"}
{"lvl":"info","msg":"Bumping default cache on mainnet","provided":1024,"t":"2021-01-25T14:49:57.978673911+01:00","updated":4096}
{"lvl":"warn","msg":"Sanitizing cache to Go's GC limits","provided":4096,"t":"2021-01-25T14:49:57.978784402+01:00","updated":2589}
Fatal: open /bax/noz: no such file or directory

So I think this diff minus the extra log line will make it both 'safe' and functional

[s1na]

Aha this way glogger has a default value until it is more exactly configured based on flags. Updated with this patch and squashed the commits.

[holiman]

LGTM. I think this is a really nice feature, and on the upside, it doesn't actually add a lot of complexity or new code.

The only thing I'm a bit unsure about is whether logjson flag is the best name for it.

[s1na]

Another option I was thinking about would be --log.format json/human. But since there are only 2 options it seems a bit too much. Do you have any ideas Martin?

[holiman]

I think maybe I'd prefer just --log.json

[holiman]

@s1na as a follow-up, can you move other flags into the logs. namespace, namely: log.verbosity, log.vmodule, log.backtrace ? And while doing so, make the old ones deprecated, causing them to still work, but also show a mesage about the new flags.

[willianpaixao]

Thanks @s1na and @holiman! ❤️