From 1e207342b545fb5992e2e8f38e60f219f379e5e0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Szil=C3=A1gyi?= Date: Thu, 15 Apr 2021 20:35:00 +0300 Subject: [PATCH] all: make logs a bit easier on the eye to digest (#22665) * all: add thousandths separators for big numbers on log messages * p2p/sentry: drop accidental file * common, log: add fast number formatter * common, eth/protocols/snap: simplifty fancy num types * log: handle nil big ints --- accounts/url.go | 2 +- cmd/evm/README.md | 6 +- cmd/evm/testdata/8/readme.md | 6 +- common/types.go | 2 +- core/blockchain.go | 10 ++-- core/blockchain_test.go | 4 +- core/chain_indexer.go | 2 +- core/headerchain.go | 2 +- eth/protocols/snap/sync.go | 14 ++--- log/format.go | 106 ++++++++++++++++++++++++++++++++++- log/format_test.go | 75 +++++++++++++++++++++++++ 11 files changed, 202 insertions(+), 27 deletions(-) create mode 100644 log/format_test.go diff --git a/accounts/url.go b/accounts/url.go index a5add10216..12a84414a0 100644 --- a/accounts/url.go +++ b/accounts/url.go @@ -64,7 +64,7 @@ func (u URL) String() string { func (u URL) TerminalString() string { url := u.String() if len(url) > 32 { - return url[:31] + "…" + return url[:31] + ".." } return url } diff --git a/cmd/evm/README.md b/cmd/evm/README.md index 7742ccbbb7..cdff41f904 100644 --- a/cmd/evm/README.md +++ b/cmd/evm/README.md @@ -256,9 +256,9 @@ Error code: 4 Another thing that can be done, is to chain invocations: ``` ./evm t8n --input.alloc=./testdata/1/alloc.json --input.txs=./testdata/1/txs.json --input.env=./testdata/1/env.json --output.alloc=stdout | ./evm t8n --input.alloc=stdin --input.env=./testdata/1/env.json --input.txs=./testdata/1/txs.json -INFO [01-21|22:41:22.963] rejected tx index=1 hash="0557ba…18d673" from=0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192 error="nonce too low: address 0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192, tx: 0 state: 1" -INFO [01-21|22:41:22.966] rejected tx index=0 hash="0557ba…18d673" from=0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192 error="nonce too low: address 0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192, tx: 0 state: 1" -INFO [01-21|22:41:22.967] rejected tx index=1 hash="0557ba…18d673" from=0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192 error="nonce too low: address 0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192, tx: 0 state: 1" +INFO [01-21|22:41:22.963] rejected tx index=1 hash=0557ba..18d673 from=0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192 error="nonce too low: address 0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192, tx: 0 state: 1" +INFO [01-21|22:41:22.966] rejected tx index=0 hash=0557ba..18d673 from=0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192 error="nonce too low: address 0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192, tx: 0 state: 1" +INFO [01-21|22:41:22.967] rejected tx index=1 hash=0557ba..18d673 from=0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192 error="nonce too low: address 0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192, tx: 0 state: 1" ``` What happened here, is that we first applied two identical transactions, so the second one was rejected. diff --git a/cmd/evm/testdata/8/readme.md b/cmd/evm/testdata/8/readme.md index 778fc6151a..e021cd7e2e 100644 --- a/cmd/evm/testdata/8/readme.md +++ b/cmd/evm/testdata/8/readme.md @@ -56,8 +56,8 @@ dir=./testdata/8 \ If we try to execute it on older rules: ``` dir=./testdata/8 && ./evm t8n --state.fork=Istanbul --input.alloc=$dir/alloc.json --input.txs=$dir/txs.json --input.env=$dir/env.json -INFO [01-21|23:21:51.265] rejected tx index=0 hash="d2818d…6ab3da" error="tx type not supported" -INFO [01-21|23:21:51.265] rejected tx index=1 hash="26ea00…81c01b" from=0xa94f5374Fce5edBC8E2a8697C15331677e6EbF0B error="nonce too high: address 0xa94f5374Fce5edBC8E2a8697C15331677e6EbF0B, tx: 1 state: 0" -INFO [01-21|23:21:51.265] rejected tx index=2 hash="698d01…369cee" error="tx type not supported" +INFO [01-21|23:21:51.265] rejected tx index=0 hash=d2818d..6ab3da error="tx type not supported" +INFO [01-21|23:21:51.265] rejected tx index=1 hash=26ea00..81c01b from=0xa94f5374Fce5edBC8E2a8697C15331677e6EbF0B error="nonce too high: address 0xa94f5374Fce5edBC8E2a8697C15331677e6EbF0B, tx: 1 state: 0" +INFO [01-21|23:21:51.265] rejected tx index=2 hash=698d01..369cee error="tx type not supported" ``` Number `1` and `3` are not applicable, and therefore number `2` has wrong nonce. \ No newline at end of file diff --git a/common/types.go b/common/types.go index d920e8b1f1..d715356692 100644 --- a/common/types.go +++ b/common/types.go @@ -76,7 +76,7 @@ func (h Hash) Hex() string { return hexutil.Encode(h[:]) } // TerminalString implements log.TerminalStringer, formatting a string for console // output during logging. func (h Hash) TerminalString() string { - return fmt.Sprintf("%x…%x", h[:3], h[29:]) + return fmt.Sprintf("%x..%x", h[:3], h[29:]) } // String implements the stringer interface and is used also by the logger when diff --git a/core/blockchain.go b/core/blockchain.go index d65ce4f048..8c3d940a69 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -630,7 +630,7 @@ func (bc *BlockChain) FastSyncCommitHead(hash common.Hash) error { // Make sure that both the block as well at its state trie exists block := bc.GetBlockByHash(hash) if block == nil { - return fmt.Errorf("non existent block [%x…]", hash[:4]) + return fmt.Errorf("non existent block [%x..]", hash[:4]) } if _, err := trie.NewSecure(block.Root(), bc.stateCache.TrieDB()); err != nil { return err @@ -1147,7 +1147,7 @@ func (bc *BlockChain) InsertReceiptChain(blockChain types.Blocks, receiptChain [ if blockChain[i].NumberU64() != blockChain[i-1].NumberU64()+1 || blockChain[i].ParentHash() != blockChain[i-1].Hash() { log.Error("Non contiguous receipt insert", "number", blockChain[i].Number(), "hash", blockChain[i].Hash(), "parent", blockChain[i].ParentHash(), "prevnumber", blockChain[i-1].Number(), "prevhash", blockChain[i-1].Hash()) - return 0, fmt.Errorf("non contiguous insert: item %d is #%d [%x…], item %d is #%d [%x…] (parent [%x…])", i-1, blockChain[i-1].NumberU64(), + return 0, fmt.Errorf("non contiguous insert: item %d is #%d [%x..], item %d is #%d [%x..] (parent [%x..])", i-1, blockChain[i-1].NumberU64(), blockChain[i-1].Hash().Bytes()[:4], i, blockChain[i].NumberU64(), blockChain[i].Hash().Bytes()[:4], blockChain[i].ParentHash().Bytes()[:4]) } } @@ -1212,7 +1212,7 @@ func (bc *BlockChain) InsertReceiptChain(blockChain types.Blocks, receiptChain [ } // Short circuit if the owner header is unknown if !bc.HasHeader(block.Hash(), block.NumberU64()) { - return i, fmt.Errorf("containing header #%d [%x…] unknown", block.Number(), block.Hash().Bytes()[:4]) + return i, fmt.Errorf("containing header #%d [%x..] unknown", block.Number(), block.Hash().Bytes()[:4]) } var ( start = time.Now() @@ -1356,7 +1356,7 @@ func (bc *BlockChain) InsertReceiptChain(blockChain types.Blocks, receiptChain [ } // Short circuit if the owner header is unknown if !bc.HasHeader(block.Hash(), block.NumberU64()) { - return i, fmt.Errorf("containing header #%d [%x…] unknown", block.Number(), block.Hash().Bytes()[:4]) + return i, fmt.Errorf("containing header #%d [%x..] unknown", block.Number(), block.Hash().Bytes()[:4]) } if !skipPresenceCheck { // Ignore if the entire data is already known @@ -1679,7 +1679,7 @@ func (bc *BlockChain) InsertChain(chain types.Blocks) (int, error) { log.Error("Non contiguous block insert", "number", block.Number(), "hash", block.Hash(), "parent", block.ParentHash(), "prevnumber", prev.Number(), "prevhash", prev.Hash()) - return 0, fmt.Errorf("non contiguous insert: item %d is #%d [%x…], item %d is #%d [%x…] (parent [%x…])", i-1, prev.NumberU64(), + return 0, fmt.Errorf("non contiguous insert: item %d is #%d [%x..], item %d is #%d [%x..] (parent [%x..])", i-1, prev.NumberU64(), prev.Hash().Bytes()[:4], i, block.NumberU64(), block.Hash().Bytes()[:4], block.ParentHash().Bytes()[:4]) } } diff --git a/core/blockchain_test.go b/core/blockchain_test.go index fd7f1aea1b..5004abd1c7 100644 --- a/core/blockchain_test.go +++ b/core/blockchain_test.go @@ -1462,13 +1462,13 @@ func TestBlockchainHeaderchainReorgConsistency(t *testing.T) { t.Fatalf("block %d: failed to insert into chain: %v", i, err) } if chain.CurrentBlock().Hash() != chain.CurrentHeader().Hash() { - t.Errorf("block %d: current block/header mismatch: block #%d [%x…], header #%d [%x…]", i, chain.CurrentBlock().Number(), chain.CurrentBlock().Hash().Bytes()[:4], chain.CurrentHeader().Number, chain.CurrentHeader().Hash().Bytes()[:4]) + t.Errorf("block %d: current block/header mismatch: block #%d [%x..], header #%d [%x..]", i, chain.CurrentBlock().Number(), chain.CurrentBlock().Hash().Bytes()[:4], chain.CurrentHeader().Number, chain.CurrentHeader().Hash().Bytes()[:4]) } if _, err := chain.InsertChain(forks[i : i+1]); err != nil { t.Fatalf(" fork %d: failed to insert into chain: %v", i, err) } if chain.CurrentBlock().Hash() != chain.CurrentHeader().Hash() { - t.Errorf(" fork %d: current block/header mismatch: block #%d [%x…], header #%d [%x…]", i, chain.CurrentBlock().Number(), chain.CurrentBlock().Hash().Bytes()[:4], chain.CurrentHeader().Number, chain.CurrentHeader().Hash().Bytes()[:4]) + t.Errorf(" fork %d: current block/header mismatch: block #%d [%x..], header #%d [%x..]", i, chain.CurrentBlock().Number(), chain.CurrentBlock().Hash().Bytes()[:4], chain.CurrentHeader().Number, chain.CurrentHeader().Hash().Bytes()[:4]) } } } diff --git a/core/chain_indexer.go b/core/chain_indexer.go index 4b326c970b..95901a0eaa 100644 --- a/core/chain_indexer.go +++ b/core/chain_indexer.go @@ -401,7 +401,7 @@ func (c *ChainIndexer) processSection(section uint64, lastHead common.Hash) (com } header := rawdb.ReadHeader(c.chainDb, hash, number) if header == nil { - return common.Hash{}, fmt.Errorf("block #%d [%x…] not found", number, hash[:4]) + return common.Hash{}, fmt.Errorf("block #%d [%x..] not found", number, hash[:4]) } else if header.ParentHash != lastHead { return common.Hash{}, fmt.Errorf("chain reorged during section processing") } diff --git a/core/headerchain.go b/core/headerchain.go index 9aee660eba..1dbf958786 100644 --- a/core/headerchain.go +++ b/core/headerchain.go @@ -306,7 +306,7 @@ func (hc *HeaderChain) ValidateHeaderChain(chain []*types.Header, checkFreq int) log.Error("Non contiguous header insert", "number", chain[i].Number, "hash", hash, "parent", chain[i].ParentHash, "prevnumber", chain[i-1].Number, "prevhash", parentHash) - return 0, fmt.Errorf("non contiguous insert: item %d is #%d [%x…], item %d is #%d [%x…] (parent [%x…])", i-1, chain[i-1].Number, + return 0, fmt.Errorf("non contiguous insert: item %d is #%d [%x..], item %d is #%d [%x..] (parent [%x..])", i-1, chain[i-1].Number, parentHash.Bytes()[:4], i, chain[i].Number, hash.Bytes()[:4], chain[i].ParentHash[:4]) } // If the header is a banned one, straight out abort diff --git a/eth/protocols/snap/sync.go b/eth/protocols/snap/sync.go index 22b0c8604d..1ea589c7b2 100644 --- a/eth/protocols/snap/sync.go +++ b/eth/protocols/snap/sync.go @@ -2675,9 +2675,9 @@ func (s *Syncer) reportSyncProgress(force bool) { // Create a mega progress report var ( progress = fmt.Sprintf("%.2f%%", float64(synced)*100/estBytes) - accounts = fmt.Sprintf("%d@%v", s.accountSynced, s.accountBytes.TerminalString()) - storage = fmt.Sprintf("%d@%v", s.storageSynced, s.storageBytes.TerminalString()) - bytecode = fmt.Sprintf("%d@%v", s.bytecodeSynced, s.bytecodeBytes.TerminalString()) + accounts = fmt.Sprintf("%v@%v", log.FormatLogfmtUint64(s.accountSynced), s.accountBytes.TerminalString()) + storage = fmt.Sprintf("%v@%v", log.FormatLogfmtUint64(s.storageSynced), s.storageBytes.TerminalString()) + bytecode = fmt.Sprintf("%v@%v", log.FormatLogfmtUint64(s.bytecodeSynced), s.bytecodeBytes.TerminalString()) ) log.Info("State sync in progress", "synced", progress, "state", synced, "accounts", accounts, "slots", storage, "codes", bytecode, "eta", common.PrettyDuration(estTime-elapsed)) @@ -2693,10 +2693,10 @@ func (s *Syncer) reportHealProgress(force bool) { // Create a mega progress report var ( - trienode = fmt.Sprintf("%d@%v", s.trienodeHealSynced, s.trienodeHealBytes.TerminalString()) - bytecode = fmt.Sprintf("%d@%v", s.bytecodeHealSynced, s.bytecodeHealBytes.TerminalString()) - accounts = fmt.Sprintf("%d@%v", s.accountHealed, s.accountHealedBytes.TerminalString()) - storage = fmt.Sprintf("%d@%v", s.storageHealed, s.storageHealedBytes.TerminalString()) + trienode = fmt.Sprintf("%v@%v", log.FormatLogfmtUint64(s.trienodeHealSynced), s.trienodeHealBytes.TerminalString()) + bytecode = fmt.Sprintf("%v@%v", log.FormatLogfmtUint64(s.bytecodeHealSynced), s.bytecodeHealBytes.TerminalString()) + accounts = fmt.Sprintf("%v@%v", log.FormatLogfmtUint64(s.accountHealed), s.accountHealedBytes.TerminalString()) + storage = fmt.Sprintf("%v@%v", log.FormatLogfmtUint64(s.storageHealed), s.storageHealedBytes.TerminalString()) ) log.Info("State heal in progress", "accounts", accounts, "slots", storage, "codes", bytecode, "nodes", trienode, "pending", s.healer.scheduler.Pending()) diff --git a/log/format.go b/log/format.go index 421384cc1d..0667921528 100644 --- a/log/format.go +++ b/log/format.go @@ -4,6 +4,7 @@ import ( "bytes" "encoding/json" "fmt" + "math/big" "reflect" "strconv" "strings" @@ -329,11 +330,20 @@ func formatLogfmtValue(value interface{}, term bool) string { return "nil" } - if t, ok := value.(time.Time); ok { + switch v := value.(type) { + case time.Time: // Performance optimization: No need for escaping since the provided // timeFormat doesn't have any escape characters, and escaping is // expensive. - return t.Format(timeFormat) + return v.Format(timeFormat) + + case *big.Int: + // Big ints get consumed by the Stringer clause so we need to handle + // them earlier on. + if v == nil { + return "" + } + return formatLogfmtBigInt(v) } if term { if s, ok := value.(TerminalStringer); ok { @@ -349,8 +359,24 @@ func formatLogfmtValue(value interface{}, term bool) string { return strconv.FormatFloat(float64(v), floatFormat, 3, 64) case float64: return strconv.FormatFloat(v, floatFormat, 3, 64) - case int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64: + case int8, uint8: return fmt.Sprintf("%d", value) + case int: + return FormatLogfmtInt64(int64(v)) + case int16: + return FormatLogfmtInt64(int64(v)) + case int32: + return FormatLogfmtInt64(int64(v)) + case int64: + return FormatLogfmtInt64(v) + case uint: + return FormatLogfmtUint64(uint64(v)) + case uint16: + return FormatLogfmtUint64(uint64(v)) + case uint32: + return FormatLogfmtUint64(uint64(v)) + case uint64: + return FormatLogfmtUint64(v) case string: return escapeString(v) default: @@ -358,6 +384,80 @@ func formatLogfmtValue(value interface{}, term bool) string { } } +// FormatLogfmtInt64 formats a potentially big number in a friendlier split format. +func FormatLogfmtInt64(n int64) string { + if n < 0 { + return formatLogfmtUint64(uint64(-n), true) + } + return formatLogfmtUint64(uint64(n), false) +} + +// FormatLogfmtUint64 formats a potentially big number in a friendlier split format. +func FormatLogfmtUint64(n uint64) string { + return formatLogfmtUint64(n, false) +} + +func formatLogfmtUint64(n uint64, neg bool) string { + // Small numbers are fine as is + if n < 100000 { + if neg { + return strconv.Itoa(-int(n)) + } else { + return strconv.Itoa(int(n)) + } + } + // Large numbers should be split + const maxLength = 26 + + var ( + out = make([]byte, maxLength) + i = maxLength - 1 + comma = 0 + ) + for ; n > 0; i-- { + if comma == 3 { + comma = 0 + out[i] = ',' + } else { + comma++ + out[i] = '0' + byte(n%10) + n /= 10 + } + } + if neg { + out[i] = '-' + i-- + } + return string(out[i+1:]) +} + +var big1000 = big.NewInt(1000) + +// formatLogfmtBigInt formats a potentially gigantic number in a friendlier split +// format. +func formatLogfmtBigInt(n *big.Int) string { + // Most number don't need fancy handling, just downcast + if n.IsUint64() { + return FormatLogfmtUint64(n.Uint64()) + } + if n.IsInt64() { + return FormatLogfmtInt64(n.Int64()) + } + // Ok, huge number needs huge effort + groups := make([]string, 0, 8) // random initial size to cover most cases + for n.Cmp(big1000) >= 0 { + _, mod := n.DivMod(n, big1000, nil) + groups = append(groups, fmt.Sprintf("%03d", mod)) + } + groups = append(groups, n.String()) + + last := len(groups) - 1 + for i := 0; i < len(groups)/2; i++ { + groups[i], groups[last-i] = groups[last-i], groups[i] + } + return strings.Join(groups, ",") +} + // escapeString checks if the provided string needs escaping/quoting, and // calls strconv.Quote if needed func escapeString(s string) string { diff --git a/log/format_test.go b/log/format_test.go new file mode 100644 index 0000000000..348b265c9b --- /dev/null +++ b/log/format_test.go @@ -0,0 +1,75 @@ +package log + +import ( + "math" + "math/rand" + "testing" +) + +func TestPrettyInt64(t *testing.T) { + tests := []struct { + n int64 + s string + }{ + {0, "0"}, + {10, "10"}, + {-10, "-10"}, + {100, "100"}, + {-100, "-100"}, + {1000, "1000"}, + {-1000, "-1000"}, + {10000, "10000"}, + {-10000, "-10000"}, + {99999, "99999"}, + {-99999, "-99999"}, + {100000, "100,000"}, + {-100000, "-100,000"}, + {1000000, "1,000,000"}, + {-1000000, "-1,000,000"}, + {math.MaxInt64, "9,223,372,036,854,775,807"}, + {math.MinInt64, "-9,223,372,036,854,775,808"}, + } + for i, tt := range tests { + if have := FormatLogfmtInt64(tt.n); have != tt.s { + t.Errorf("test %d: format mismatch: have %s, want %s", i, have, tt.s) + } + } +} + +func TestPrettyUint64(t *testing.T) { + tests := []struct { + n uint64 + s string + }{ + {0, "0"}, + {10, "10"}, + {100, "100"}, + {1000, "1000"}, + {10000, "10000"}, + {99999, "99999"}, + {100000, "100,000"}, + {1000000, "1,000,000"}, + {math.MaxUint64, "18,446,744,073,709,551,615"}, + } + for i, tt := range tests { + if have := FormatLogfmtUint64(tt.n); have != tt.s { + t.Errorf("test %d: format mismatch: have %s, want %s", i, have, tt.s) + } + } +} + +var sink string + +func BenchmarkPrettyInt64Logfmt(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + sink = FormatLogfmtInt64(rand.Int63()) + } +} + +func BenchmarkPrettyUint64Logfmt(b *testing.B) { + b.ReportAllocs() + for i := 0; i < b.N; i++ { + sink = FormatLogfmtUint64(rand.Uint64()) + } +}