cmd/geth: test for logging-output

[holiman]

This PR is a bit in preparation for the slog work in #28187 .

Our current test re logging mostly test the internals, but we have no real end-to-end test of the logging output. This PR introduces a simple reexec-based log tester. This also relies upon a special mode in geth, which can be made to eject a set of predefined log messages.

e.g. geth --log.format terminal logtest .

If we decide to use this approach, we can remove many other tests, e.g. in format_test.go. With this approach, we can swap out our internal logging engine but not actually modfiy the tests (except modifying the expected outputs, if we want to).

While working on this, I also noticed a quirk in the setup: when geth was configured to use a file output, then two separate handlers were used (one handler for the file, one handler for the console). Using two separate handlers means that two formatters are used, thus the formatting of any/all records happened twice. This PR changes the mechanism to use two separate io.Writers instead, which is both more optimal and fixes a bug which occurs due to a global statefulness in the formatter.

---

One annoying thing is that my approach works for terminal and logfmt, but not json, since locating and censoring the json timestamp is not as trivial.

[jwasinger]

Yeah, it's unfortunate that there's no spec-defined ordering for json keys.

[holiman]

Yeah, it's unfortunate that there's no spec-defined ordering for json keys.

Oh ISTR that the golang json lib we use does have deterministic ordering. But the actual timestamp will land on different indexes on each line, so although it may be deterministic, it's not as simple as the other two where I can just blank out certain byte-indexes.

[jwasinger]

slog doesn't use the json library to encode records. it does it on its own, and the ordering of keys is different.

slog:
{"time":"2023-10-18T19:25:16.528617+08:00","level":"WARN","msg":"Unclean shutdown detected","booted":"2023-10-16T17:32:38+08:00","age":{}}

ours:
{"age":"3mo3d17h","booted":"2023-07-17T01:52:45+0800","lvl":"warn","msg":"Unclean shutdown detected","t":"2023-10-18T19:25:53.34273+08:00"}

The ordering is different (disregarding the inconsistencies in key names/values which I'm trying to fix).

[jwasinger]

so doing it this way might be too restrictive for json only b/c of the lack of defined ordering for keys.

[holiman]

so doing it this way might be too restrictive for json only b/c of the lack of defined ordering for keys.

Yes, for json we need something else. On the other hand, json is very well defined. I'm not very worried about it breaking: as long as the json marshaller outputs valid json, there's not a whole lot of things that can go wrong. (it can e..g fail to invoke stringer()-types, but it won't fail to encode a bash escape)

[holiman]

One thing I noticed while doing the log-tests , is that if we use --log.file=/foo/bar, then we pipe logs to both terminal and that file. However: it seems that it's not actually 'dumb copy', what we use is two handlers with identical formatters and different outputs. So each log-invocation causes two records to be formatted individually, effectively doubling the processing overhead.

We could use a custom "both terminal and file" handler like this:

func PipeHandler(fmtr Format, terminal io.Writer, path string) (Handler, error) {
	f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
	if err != nil {
		return nil, err
	}
	return FuncHandler(func(r *Record) error {
		out := fmtr.Format(r)
		terminal.Write(out)
		_, err := f.Write(out)
		return err
	}), nil
}

But it doesn't seem worth it to optimize the log stuff now, since we're moving to slog later on. Would be nice to use that trick later on though.

[holiman]

The double-output-processing is now fixed in this PR.

[holiman]

Adding this for triage discussion: it adds another command, geth logtest, which might be a tad controversial...

[holiman]

Suggested change

	// This sequence of logs should be output with alignment, so each field becoems a column.
	// This sequence of logs should be output with alignment, so each field becomes a column.

[holiman]

Adding this for triage discussion: it adds another command, geth logtest, which might be a tad controversial...

triage discussion: look into using a build tag, to only add the extra command when run in testing

[holiman]

It's now disabled unless the tag integrationtests is used:

[user@work go-ethereum]$ go run -tags=integrationtests ./cmd/geth --log.format terminal logtest 2>&1  | head
INFO [10-25|12:28:53.656] big.Int                                  111,222,333,444,555,678,999=111,222,333,444,555,678,999
INFO [10-25|12:28:53.656] -big.Int                                 -111,222,333,444,555,678,999=-111,222,333,444,555,678,999
INFO [10-25|12:28:53.656] big.Int                                  11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
INFO [10-25|12:28:53.656] -big.Int                                 -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900
INFO [10-25|12:28:53.656] uint256                                  111,222,333,444,555,678,999=111,222,333,444,555,678,999
INFO [10-25|12:28:53.656] uint256                                  11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
INFO [10-25|12:28:53.656] int64                                    1,000,000=1,000,000
INFO [10-25|12:28:53.656] int64                                    -1,000,000=-1,000,000
INFO [10-25|12:28:53.656] int64                                    9,223,372,036,854,775,807=9,223,372,036,854,775,807
INFO [10-25|12:28:53.656] int64                                    -9,223,372,036,854,775,808=-9,223,372,036,854,775,808
[user@work go-ethereum]$ go run  ./cmd/geth --log.format terminal logtest 2>&1  | head
invalid command: "logtest"
exit status 1

and

[user@work go-ethereum]$ go test ./cmd/geth -tags=integrationtests  -v -run TestLogging
=== RUN   TestLogging
--- PASS: TestLogging (0.10s)
PASS
ok      github.com/ethereum/go-ethereum/cmd/geth        (cached)
[user@work go-ethereum]$ go test ./cmd/geth   -v -run TestLogging
testing: warning: no tests to run
PASS
ok      github.com/ethereum/go-ethereum/cmd/geth        0.081s [no tests to run]

[holiman]

The ordering is different (disregarding the inconsistencies in key names/values which I'm trying to fix).

btw @jwasinger -- I don't think changing t to time is a bad thing, rather it's a good thing. Same with level. However, "age":{}} -- that's not nice at all