Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

all: make logs a bit easier on the eye to digest #22665

Merged
merged 5 commits into from
Apr 15, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion accounts/url.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand Down
6 changes: 3 additions & 3 deletions cmd/evm/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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="0557ba18d673" from=0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192 error="nonce too low: address 0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192, tx: 0 state: 1"
INFO [01-21|22:41:22.966] rejected tx index=0 hash="0557ba18d673" from=0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192 error="nonce too low: address 0x8A8eAFb1cf62BfBeb1741769DAE1a9dd47996192, tx: 0 state: 1"
INFO [01-21|22:41:22.967] rejected tx index=1 hash="0557ba18d673" 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.
Expand Down
6 changes: 3 additions & 3 deletions cmd/evm/testdata/8/readme.md
Original file line number Diff line number Diff line change
Expand Up @@ -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="d2818d6ab3da" error="tx type not supported"
INFO [01-21|23:21:51.265] rejected tx index=1 hash="26ea0081c01b" from=0xa94f5374Fce5edBC8E2a8697C15331677e6EbF0B error="nonce too high: address 0xa94f5374Fce5edBC8E2a8697C15331677e6EbF0B, tx: 1 state: 0"
INFO [01-21|23:21:51.265] rejected tx index=2 hash="698d01369cee" 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.
2 changes: 1 addition & 1 deletion common/types.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
10 changes: 5 additions & 5 deletions core/blockchain.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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])
}
}
Expand Down Expand Up @@ -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()
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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])
}
}
Expand Down
4 changes: 2 additions & 2 deletions core/blockchain_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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])
}
}
}
Expand Down
2 changes: 1 addition & 1 deletion core/chain_indexer.go
Original file line number Diff line number Diff line change
Expand Up @@ -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")
}
Expand Down
2 changes: 1 addition & 1 deletion core/headerchain.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
14 changes: 7 additions & 7 deletions eth/protocols/snap/sync.go
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand All @@ -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())
Expand Down
106 changes: 103 additions & 3 deletions log/format.go
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ import (
"bytes"
"encoding/json"
"fmt"
"math/big"
"reflect"
"strconv"
"strings"
Expand Down Expand Up @@ -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 "<nil>"
}
return formatLogfmtBigInt(v)
}
if term {
if s, ok := value.(TerminalStringer); ok {
Expand All @@ -349,15 +359,105 @@ 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:
return escapeString(fmt.Sprintf("%+v", value))
}
}

// 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 {
Expand Down
75 changes: 75 additions & 0 deletions log/format_test.go
Original file line number Diff line number Diff line change
@@ -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())
}
}