Node discovery periodically revalidates the nodes in its table by sending PING, checking
if they are still alive. I recently noticed some issues with the implementation of this
process, which can cause strange results such as nodes dropping unexpectedly, certain
nodes not getting revalidated often enough, and bad results being returned to incoming
FINDNODE queries.
In this change, the revalidation process is improved with the following logic:
- We maintain two 'revalidation lists' containing the table nodes, named 'fast' and 'slow'.
- The process chooses random nodes from each list on a randomized interval, the interval being
faster for the 'fast' list, and performs revalidation for the chosen node.
- Whenever a node is newly inserted into the table, it goes into the 'fast' list.
Once validation passes, it transfers to the 'slow' list. If a request fails, or the
node changes endpoint, it transfers back into 'fast'.
- livenessChecks is incremented by one for successful checks. Unlike the old implementation,
we will not drop the node on the first failing check. We instead quickly decay the
livenessChecks give it another chance.
- Order of nodes in bucket doesn't matter anymore.
I am also adding a debug API endpoint to dump the node table content.
Co-authored-by: Martin HS <martin@swende.se>
This change
- Removes interface `log.Format`,
- Removes method `log.FormatFunc`,
- unexports `TerminalHandler.TerminalFormat` formatting methods (renamed to `TerminalHandler.format`)
- removes the notion of `log.Lazy` values
The lazy handler was useful in the old log package, since it
could defer the evaluation of costly attributes until later in the
log pipeline: thus, if the logging was done at 'Trace', we could
skip evaluation if logging only was set to 'Info'.
With the move to slog, this way of deferring evaluation is no longer
needed, since slog introduced 'Enabled': the caller can thus do
the evaluate-or-not decision at the callsite, which is much more
straight-forward than dealing with lazy reflect-based evaluation.
Also, lazy evaluation would not work with 'native' slog, as in, these
two statements would be evaluated differently:
```golang
log.Info("foo", "my lazy", lazyObj)
slog.Info("foo", "my lazy", lazyObj)
```
These changes improves the performance of the non-coloured terminal formatting, _quite a lot_.
```
name old time/op new time/op delta
TerminalHandler-8 10.2µs ±15% 5.4µs ± 9% -47.02% (p=0.008 n=5+5)
name old alloc/op new alloc/op delta
TerminalHandler-8 2.17kB ± 0% 0.40kB ± 0% -81.46% (p=0.008 n=5+5)
name old allocs/op new allocs/op delta
TerminalHandler-8 33.0 ± 0% 5.0 ± 0% -84.85% (p=0.008 n=5+5)
```
I tried to _somewhat_ organize the commits, but the it might still be a bit chaotic. Some core insights:
- The function `terminalHandler.Handl` uses a mutex, and writes all output immediately to 'upstream'. Thus, it can reuse a scratch-buffer every time.
- This buffer can be propagated internally, making all the internal formatters either write directly to it,
- OR, make use of the `tmp := buf.AvailableBuffer()` in some cases, where a byte buffer "extra capacity" can be temporarily used.
- The `slog` package uses `Attr` by value. It makes sense to minimize operating on them, since iterating / collecting into a new slice, iterating again etc causes copy-on-heap. Better to operate on them only once.
- If we want to do padding, it's better to copy from a constant `space`-buffer than to invoke `bytes.Repeat` every single time.
This PR replaces Geth's logger package (a fork of [log15](https://github.com/inconshreveable/log15)) with an implementation using slog, a logging library included as part of the Go standard library as of Go1.21.
Main changes are as follows:
* removes any log handlers that were unused in the Geth codebase.
* Json, logfmt, and terminal formatters are now slog handlers.
* Verbosity level constants are changed to match slog constant values. Internal translation is done to make this opaque to the user and backwards compatible with existing `--verbosity` and `--vmodule` options.
* `--log.backtraceat` and `--log.debug` are removed.
The external-facing API is largely the same as the existing Geth logger. Logger method signatures remain unchanged.
A small semantic difference is that a `Handler` can only be set once per `Logger` and not changed dynamically. This just means that a new logger must be instantiated every time the handler of the root logger is changed.
----
For users of the `go-ethereum/log` module. If you were using this module for your own project, you will need to change the initialization. If you previously did
```golang
log.Root().SetHandler(log.LvlFilterHandler(log.LvlInfo, log.StreamHandler(os.Stderr, log.TerminalFormat(true))))
```
You now instead need to do
```golang
log.SetDefault(log.NewLogger(log.NewTerminalHandlerWithLevel(os.Stderr, log.LevelInfo, true)))
```
See more about reasoning here: https://github.com/ethereum/go-ethereum/issues/28558#issuecomment-1820606613
* internal/testlog: print file+line number of log call in test log
This changes the unit test logger to print the actual file and line
number of the logging call instead of "testlog.go:44".
Output of 'go test -v -run TestServerListen ./p2p' before this change:
=== RUN TestServerListen
--- PASS: TestServerListen (0.00s)
testlog.go:44: DEBUG[01-08|15:16:31.651] UDP listener up addr=127.0.0.1:62678
testlog.go:44: DEBUG[01-08|15:16:31.651] TCP listener up addr=127.0.0.1:62678
testlog.go:44: TRACE[01-08|15:16:31.652] Accepted connection addr=127.0.0.1:62679
And after:
=== RUN TestServerListen
--- PASS: TestServerListen (0.00s)
server.go:868: DEBUG[01-08|15:25:35.679] TCP listener up addr=127.0.0.1:62712
server.go:557: DEBUG[01-08|15:25:35.679] UDP listener up addr=127.0.0.1:62712
server.go:912: TRACE[01-08|15:25:35.680] Accepted connection addr=127.0.0.1:62713
* internal/testlog: document use of t.Helper
Felix Lange
Martin HS
Sebastian Stammler
jwasinger
Péter Szilágyi