From f2b509d8a1ae877e2edb03560e57236eb74816b7 Mon Sep 17 00:00:00 2001 From: BorkBorked <107079055+BorkBorked@users.noreply.github.com> Date: Fri, 1 Dec 2023 09:51:50 +0100 Subject: [PATCH 1/3] accounts/abi/bind: fix typo (#28630) --- accounts/abi/bind/util_test.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/accounts/abi/bind/util_test.go b/accounts/abi/bind/util_test.go index b34c5bc226..16110b5d27 100644 --- a/accounts/abi/bind/util_test.go +++ b/accounts/abi/bind/util_test.go @@ -119,9 +119,9 @@ func TestWaitDeployedCornerCases(t *testing.T) { defer cancel() backend.SendTransaction(ctx, tx) backend.Commit() - notContentCreation := errors.New("tx is not contract creation") - if _, err := bind.WaitDeployed(ctx, backend, tx); err.Error() != notContentCreation.Error() { - t.Errorf("error mismatch: want %q, got %q, ", notContentCreation, err) + notContractCreation := errors.New("tx is not contract creation") + if _, err := bind.WaitDeployed(ctx, backend, tx); err.Error() != notContractCreation.Error() { + t.Errorf("error mismatch: want %q, got %q, ", notContractCreation, err) } // Create a transaction that is not mined. From dd0d0a2522ccad6bdeab1e84ff577bd5826540ee Mon Sep 17 00:00:00 2001 From: Martin Holst Swende Date: Fri, 1 Dec 2023 13:28:20 +0100 Subject: [PATCH 2/3] slog: faster and less memory-consumption (#28621) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- internal/testlog/testlog.go | 3 +- log/format.go | 358 ++++++++++++++++++++---------------- log/format_test.go | 8 +- log/handler.go | 6 +- log/logger_test.go | 121 ++++++++++++ 5 files changed, 332 insertions(+), 164 deletions(-) diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index 68b9fb19f8..a7899c8158 100644 --- a/internal/testlog/testlog.go +++ b/internal/testlog/testlog.go @@ -183,8 +183,7 @@ func (h *bufHandler) terminalFormat(r slog.Record) string { } for _, attr := range attrs { - rawVal := attr.Value.Any() - fmt.Fprintf(buf, " %s=%s", attr.Key, log.FormatLogfmtValue(rawVal, true)) + fmt.Fprintf(buf, " %s=%s", attr.Key, string(log.FormatSlogValue(attr.Value, true, nil))) } buf.WriteByte('\n') return buf.String() diff --git a/log/format.go b/log/format.go index 5cbbe3341e..a2bbcce9c0 100644 --- a/log/format.go +++ b/log/format.go @@ -15,12 +15,14 @@ import ( const ( timeFormat = "2006-01-02T15:04:05-0700" - termTimeFormat = "01-02|15:04:05.000" floatFormat = 'f' termMsgJust = 40 termCtxMaxPadding = 40 ) +// 40 spaces +var spaces = []byte(" ") + type Format interface { Format(r slog.Record) []byte } @@ -44,37 +46,47 @@ type TerminalStringer interface { TerminalString() string } -func (h *TerminalHandler) TerminalFormat(r slog.Record, usecolor bool) []byte { +func (h *TerminalHandler) TerminalFormat(buf []byte, r slog.Record, usecolor bool) []byte { msg := escapeMessage(r.Message) - var color = 0 + var color = "" if usecolor { switch r.Level { case LevelCrit: - color = 35 + color = "\x1b[35m" case slog.LevelError: - color = 31 + color = "\x1b[31m" case slog.LevelWarn: - color = 33 + color = "\x1b[33m" case slog.LevelInfo: - color = 32 + color = "\x1b[32m" case slog.LevelDebug: - color = 36 + color = "\x1b[36m" case LevelTrace: - color = 34 + color = "\x1b[34m" } } - - b := &bytes.Buffer{} - lvl := LevelAlignedString(r.Level) - if color > 0 { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s] %s ", color, lvl, r.Time.Format(termTimeFormat), msg) - } else { - fmt.Fprintf(b, "%s[%s] %s ", lvl, r.Time.Format(termTimeFormat), msg) + if buf == nil { + buf = make([]byte, 0, 30+termMsgJust) } + b := bytes.NewBuffer(buf) + + if color != "" { // Start color + b.WriteString(color) + b.WriteString(LevelAlignedString(r.Level)) + b.WriteString("\x1b[0m") + } else { + b.WriteString(LevelAlignedString(r.Level)) + } + b.WriteString("[") + writeTimeTermFormat(b, r.Time) + b.WriteString("] ") + b.WriteString(msg) + // try to justify the log output for short messages - length := utf8.RuneCountInString(msg) - if r.NumAttrs() > 0 && length < termMsgJust { - b.Write(bytes.Repeat([]byte{' '}, termMsgJust-length)) + //length := utf8.RuneCountInString(msg) + length := len(msg) + if (r.NumAttrs()+len(h.attrs)) > 0 && length < termMsgJust { + b.Write(spaces[:termMsgJust-length]) } // print the keys logfmt style h.logfmt(b, r, color) @@ -82,150 +94,139 @@ func (h *TerminalHandler) TerminalFormat(r slog.Record, usecolor bool) []byte { return b.Bytes() } -func (h *TerminalHandler) logfmt(buf *bytes.Buffer, r slog.Record, color int) { - attrs := []slog.Attr{} - r.Attrs(func(attr slog.Attr) bool { - attrs = append(attrs, attr) - return true - }) +func (h *TerminalHandler) logfmt(buf *bytes.Buffer, r slog.Record, color string) { + // tmp is a temporary buffer we use, until bytes.Buffer.AvailableBuffer() (1.21) + // can be used. + var tmp = make([]byte, 40) + writeAttr := func(attr slog.Attr, first, last bool) { + buf.WriteByte(' ') - attrs = append(h.attrs, attrs...) - - for i, attr := range attrs { - if i != 0 { - buf.WriteByte(' ') - } - - key := escapeString(attr.Key) - rawVal := attr.Value.Any() - val := FormatLogfmtValue(rawVal, true) - - // XXX: we should probably check that all of your key bytes aren't invalid - // TODO (jwasinger) above comment was from log15 code. what does it mean? check that key bytes are ascii characters? - padding := h.fieldPadding[key] - - length := utf8.RuneCountInString(val) - if padding < length && length <= termCtxMaxPadding { - padding = length - h.fieldPadding[key] = padding - } - if color > 0 { - fmt.Fprintf(buf, "\x1b[%dm%s\x1b[0m=", color, key) + if color != "" { + buf.WriteString(color) + //buf.Write(appendEscapeString(buf.AvailableBuffer(), attr.Key)) + buf.Write(appendEscapeString(tmp[:0], attr.Key)) + buf.WriteString("\x1b[0m=") } else { - buf.WriteString(key) + //buf.Write(appendEscapeString(buf.AvailableBuffer(), attr.Key)) + buf.Write(appendEscapeString(tmp[:0], attr.Key)) buf.WriteByte('=') } - buf.WriteString(val) - if i < r.NumAttrs()-1 && padding > length { - buf.Write(bytes.Repeat([]byte{' '}, padding-length)) + //val := FormatSlogValue(attr.Value, true, buf.AvailableBuffer()) + val := FormatSlogValue(attr.Value, true, tmp[:0]) + + padding := h.fieldPadding[attr.Key] + + length := utf8.RuneCount(val) + if padding < length && length <= termCtxMaxPadding { + padding = length + h.fieldPadding[attr.Key] = padding + } + buf.Write(val) + if !last && padding > length { + buf.Write(spaces[:padding-length]) } } + var n = 0 + var nAttrs = len(h.attrs) + r.NumAttrs() + for _, attr := range h.attrs { + writeAttr(attr, n == 0, n == nAttrs-1) + n++ + } + r.Attrs(func(attr slog.Attr) bool { + writeAttr(attr, n == 0, n == nAttrs-1) + n++ + return true + }) buf.WriteByte('\n') } -// formatValue formats a value for serialization -func FormatLogfmtValue(value interface{}, term bool) (result string) { - if value == nil { - return "" - } +// FormatSlogValue formats a slog.Value for serialization +func FormatSlogValue(v slog.Value, term bool, tmp []byte) (result []byte) { + var value any defer func() { if err := recover(); err != nil { if v := reflect.ValueOf(value); v.Kind() == reflect.Ptr && v.IsNil() { - result = "" + result = []byte("") } else { panic(err) } } }() - switch v := value.(type) { - case time.Time: + switch v.Kind() { + case slog.KindString: + return appendEscapeString(tmp, v.String()) + case slog.KindAny: + value = v.Any() + case slog.KindInt64: // All int-types (int8 ,int16 etc) wind up here + return appendInt64(tmp, v.Int64()) + case slog.KindUint64: // All uint-types (int8 ,int16 etc) wind up here + return appendUint64(tmp, v.Uint64(), false) + case slog.KindFloat64: + return strconv.AppendFloat(tmp, v.Float64(), floatFormat, 3, 64) + case slog.KindBool: + return strconv.AppendBool(tmp, v.Bool()) + case slog.KindDuration: + value = v.Duration() + case slog.KindTime: // Performance optimization: No need for escaping since the provided // timeFormat doesn't have any escape characters, and escaping is // expensive. - return v.Format(timeFormat) - + return v.Time().AppendFormat(tmp, timeFormat) + default: + value = v.Any() + } + if value == nil { + return []byte("") + } + switch v := value.(type) { case *big.Int: // Big ints get consumed by the Stringer clause, so we need to handle // them earlier on. if v == nil { - return "" + return append(tmp, []byte("")...) } - return formatLogfmtBigInt(v) + return appendBigInt(tmp, v) case *uint256.Int: // Uint256s get consumed by the Stringer clause, so we need to handle // them earlier on. if v == nil { - return "" + return append(tmp, []byte("")...) } - return formatLogfmtUint256(v) - } - if term { - if s, ok := value.(TerminalStringer); ok { - // Custom terminal stringer provided, use that - return escapeString(s.TerminalString()) - } - } - switch v := value.(type) { + return appendU256(tmp, v) case error: - return escapeString(v.Error()) + return appendEscapeString(tmp, v.Error()) + case TerminalStringer: + if term { + return appendEscapeString(tmp, v.TerminalString()) // Custom terminal stringer provided, use that + } case fmt.Stringer: - return escapeString(v.String()) - case bool: - return strconv.FormatBool(v) - case float32: - return strconv.FormatFloat(float64(v), floatFormat, 3, 64) - case float64: - return strconv.FormatFloat(v, floatFormat, 3, 64) - case int8: - return strconv.FormatInt(int64(v), 10) - case uint8: - return strconv.FormatInt(int64(v), 10) - case int16: - return strconv.FormatInt(int64(v), 10) - case uint16: - return strconv.FormatInt(int64(v), 10) - // Larger integers get thousands separators. - case int: - return FormatLogfmtInt64(int64(v)) - case int32: - return FormatLogfmtInt64(int64(v)) - case int64: - return FormatLogfmtInt64(v) - case uint: - 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)) + return appendEscapeString(tmp, v.String()) } + + // We can use the 'tmp' as a scratch-buffer, to first format the + // value, and in a second step do escaping. + internal := fmt.Appendf(tmp, "%+v", value) + return appendEscapeString(tmp, string(internal)) } -// FormatLogfmtInt64 formats n with thousand separators. -func FormatLogfmtInt64(n int64) string { +// appendInt64 formats n with thousand separators and writes into buffer dst. +func appendInt64(dst []byte, n int64) []byte { if n < 0 { - return formatLogfmtUint64(uint64(-n), true) + return appendUint64(dst, uint64(-n), true) } - return formatLogfmtUint64(uint64(n), false) + return appendUint64(dst, uint64(n), false) } -// FormatLogfmtUint64 formats n with thousand separators. -func FormatLogfmtUint64(n uint64) string { - return formatLogfmtUint64(n, false) -} - -func formatLogfmtUint64(n uint64, neg bool) string { +// appendUint64 formats n with thousand separators and writes into buffer dst. +func appendUint64(dst []byte, n uint64, neg bool) []byte { // Small numbers are fine as is if n < 100000 { if neg { - return strconv.Itoa(-int(n)) + return strconv.AppendInt(dst, -int64(n), 10) } else { - return strconv.Itoa(int(n)) + return strconv.AppendInt(dst, int64(n), 10) } } // Large numbers should be split @@ -250,16 +251,21 @@ func formatLogfmtUint64(n uint64, neg bool) string { out[i] = '-' i-- } - return string(out[i+1:]) + return append(dst, out[i+1:]...) } -// formatLogfmtBigInt formats n with thousand separators. -func formatLogfmtBigInt(n *big.Int) string { +// FormatLogfmtUint64 formats n with thousand separators. +func FormatLogfmtUint64(n uint64) string { + return string(appendUint64(nil, n, false)) +} + +// appendBigInt formats n with thousand separators and writes to dst. +func appendBigInt(dst []byte, n *big.Int) []byte { if n.IsUint64() { - return FormatLogfmtUint64(n.Uint64()) + return appendUint64(dst, n.Uint64(), false) } if n.IsInt64() { - return FormatLogfmtInt64(n.Int64()) + return appendInt64(dst, n.Int64()) } var ( @@ -284,54 +290,48 @@ func formatLogfmtBigInt(n *big.Int) string { comma++ } } - return string(buf[i+1:]) + return append(dst, buf[i+1:]...) } -// formatLogfmtUint256 formats n with thousand separators. -func formatLogfmtUint256(n *uint256.Int) string { +// appendU256 formats n with thousand separators. +func appendU256(dst []byte, n *uint256.Int) []byte { if n.IsUint64() { - return FormatLogfmtUint64(n.Uint64()) + return appendUint64(dst, n.Uint64(), false) } - var ( - text = n.Dec() - buf = make([]byte, len(text)+len(text)/3) - comma = 0 - i = len(buf) - 1 - ) - for j := len(text) - 1; j >= 0; j, i = j-1, i-1 { - c := text[j] - - switch { - case c == '-': - buf[i] = c - case comma == 3: - buf[i] = ',' - i-- - comma = 0 - fallthrough - default: - buf[i] = c - comma++ - } - } - return string(buf[i+1:]) + res := []byte(n.PrettyDec(',')) + return append(dst, res...) } -// escapeString checks if the provided string needs escaping/quoting, and -// calls strconv.Quote if needed -func escapeString(s string) string { +// appendEscapeString writes the string s to the given writer, with +// escaping/quoting if needed. +func appendEscapeString(dst []byte, s string) []byte { needsQuoting := false + needsEscaping := false for _, r := range s { - // We quote everything below " (0x22) and above~ (0x7E), plus equal-sign - if r <= '"' || r > '~' || r == '=' { + // If it contains spaces or equal-sign, we need to quote it. + if r == ' ' || r == '=' { needsQuoting = true + continue + } + // We need to escape it, if it contains + // - character " (0x22) and lower (except space) + // - characters above ~ (0x7E), plus equal-sign + if r <= '"' || r > '~' { + needsEscaping = true break } } - if !needsQuoting { - return s + if needsEscaping { + return strconv.AppendQuote(dst, s) } - return strconv.Quote(s) + // No escaping needed, but we might have to place within quote-marks, in case + // it contained a space + if needsQuoting { + dst = append(dst, '"') + dst = append(dst, []byte(s)...) + return append(dst, '"') + } + return append(dst, []byte(s)...) } // escapeMessage checks if the provided string needs escaping/quoting, similarly @@ -356,3 +356,45 @@ func escapeMessage(s string) string { } return strconv.Quote(s) } + +// writeTimeTermFormat writes on the format "01-02|15:04:05.000" +func writeTimeTermFormat(buf *bytes.Buffer, t time.Time) { + _, month, day := t.Date() + writePosIntWidth(buf, int(month), 2) + buf.WriteByte('-') + writePosIntWidth(buf, day, 2) + buf.WriteByte('|') + hour, min, sec := t.Clock() + writePosIntWidth(buf, hour, 2) + buf.WriteByte(':') + writePosIntWidth(buf, min, 2) + buf.WriteByte(':') + writePosIntWidth(buf, sec, 2) + ns := t.Nanosecond() + buf.WriteByte('.') + writePosIntWidth(buf, ns/1e6, 3) +} + +// writePosIntWidth writes non-negative integer i to the buffer, padded on the left +// by zeroes to the given width. Use a width of 0 to omit padding. +// Adapted from golang.org/x/exp/slog/internal/buffer/buffer.go +func writePosIntWidth(b *bytes.Buffer, i, width int) { + // Cheap integer to fixed-width decimal ASCII. + // Copied from log/log.go. + if i < 0 { + panic("negative int") + } + // Assemble decimal in reverse order. + var bb [20]byte + bp := len(bb) - 1 + for i >= 10 || width > 1 { + width-- + q := i / 10 + bb[bp] = byte('0' + i - q*10) + bp-- + i = q + } + // i < 10 + bb[bp] = byte('0' + i) + b.Write(bb[bp:]) +} diff --git a/log/format_test.go b/log/format_test.go index 41e1809c38..d4c1df4abc 100644 --- a/log/format_test.go +++ b/log/format_test.go @@ -5,18 +5,20 @@ import ( "testing" ) -var sink string +var sink []byte func BenchmarkPrettyInt64Logfmt(b *testing.B) { + buf := make([]byte, 100) b.ReportAllocs() for i := 0; i < b.N; i++ { - sink = FormatLogfmtInt64(rand.Int63()) + sink = appendInt64(buf, rand.Int63()) } } func BenchmarkPrettyUint64Logfmt(b *testing.B) { + buf := make([]byte, 100) b.ReportAllocs() for i := 0; i < b.N; i++ { - sink = FormatLogfmtUint64(rand.Uint64()) + sink = appendUint64(buf, rand.Uint64(), false) } } diff --git a/log/handler.go b/log/handler.go index ef1bcc1992..1a25577450 100644 --- a/log/handler.go +++ b/log/handler.go @@ -81,6 +81,8 @@ type TerminalHandler struct { // fieldPadding is a map with maximum field value lengths seen until now // to allow padding log contexts in a bit smarter way. fieldPadding map[string]int + + buf []byte } // NewTerminalHandler returns a handler which formats log records at all levels optimized for human readability on @@ -110,7 +112,9 @@ func NewTerminalHandlerWithLevel(wr io.Writer, lvl slog.Level, useColor bool) *T func (h *TerminalHandler) Handle(_ context.Context, r slog.Record) error { h.mu.Lock() defer h.mu.Unlock() - h.wr.Write(h.TerminalFormat(r, h.useColor)) + buf := h.TerminalFormat(h.buf, r, h.useColor) + h.wr.Write(buf) + h.buf = buf[:0] return nil } diff --git a/log/logger_test.go b/log/logger_test.go index fca1f1680f..27e90c5fd2 100644 --- a/log/logger_test.go +++ b/log/logger_test.go @@ -2,10 +2,15 @@ package log import ( "bytes" + "fmt" + "io" + "math/big" "os" "strings" "testing" + "time" + "github.com/holiman/uint256" "golang.org/x/exp/slog" ) @@ -51,3 +56,119 @@ func BenchmarkTraceLogging(b *testing.B) { Trace("a message", "v", i) } } + +func BenchmarkTerminalHandler(b *testing.B) { + l := NewLogger(NewTerminalHandler(io.Discard, false)) + benchmarkLogger(b, l) +} +func BenchmarkLogfmtHandler(b *testing.B) { + l := NewLogger(LogfmtHandler(io.Discard)) + benchmarkLogger(b, l) +} + +func BenchmarkJSONHandler(b *testing.B) { + l := NewLogger(JSONHandler(io.Discard)) + benchmarkLogger(b, l) +} + +func benchmarkLogger(b *testing.B, l Logger) { + var ( + bb = make([]byte, 10) + tt = time.Now() + bigint = big.NewInt(100) + nilbig *big.Int + err = fmt.Errorf("Oh nooes it's crap") + ) + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + l.Info("This is a message", + "foo", int16(i), + "bytes", bb, + "bonk", "a string with text", + "time", tt, + "bigint", bigint, + "nilbig", nilbig, + "err", err) + } + b.StopTimer() +} + +func TestLoggerOutput(t *testing.T) { + type custom struct { + A string + B int8 + } + var ( + customA = custom{"Foo", 12} + customB = custom{"Foo\nLinebreak", 122} + bb = make([]byte, 10) + tt = time.Time{} + bigint = big.NewInt(100) + nilbig *big.Int + err = fmt.Errorf("Oh nooes it's crap") + lazy = Lazy{Fn: func() interface{} { return "lazy value" }} + smallUint = uint256.NewInt(500_000) + bigUint = &uint256.Int{0xff, 0xff, 0xff, 0xff} + ) + + out := new(bytes.Buffer) + glogHandler := NewGlogHandler(NewTerminalHandler(out, false)) + glogHandler.Verbosity(LevelInfo) + NewLogger(glogHandler).Info("This is a message", + "foo", int16(123), + "bytes", bb, + "bonk", "a string with text", + "time", tt, + "bigint", bigint, + "nilbig", nilbig, + "err", err, + "struct", customA, + "struct", customB, + "ptrstruct", &customA, + "lazy", lazy, + "smalluint", smallUint, + "bigUint", bigUint) + + have := out.String() + t.Logf("output %v", out.String()) + want := `INFO [11-07|19:14:33.821] This is a message foo=123 bytes="[0 0 0 0 0 0 0 0 0 0]" bonk="a string with text" time=0001-01-01T00:00:00+0000 bigint=100 nilbig= err="Oh nooes it's crap" struct="{A:Foo B:12}" struct="{A:Foo\nLinebreak B:122}" ptrstruct="&{A:Foo B:12}" lazy="lazy value" smalluint=500,000 bigUint=1,600,660,942,523,603,594,864,898,306,482,794,244,293,965,082,972,225,630,372,095 +` + if !bytes.Equal([]byte(have)[25:], []byte(want)[25:]) { + t.Errorf("Error\nhave: %q\nwant: %q", have, want) + } +} + +const termTimeFormat = "01-02|15:04:05.000" + +func BenchmarkAppendFormat(b *testing.B) { + var now = time.Now() + b.Run("fmt time.Format", func(b *testing.B) { + for i := 0; i < b.N; i++ { + fmt.Fprintf(io.Discard, "%s", now.Format(termTimeFormat)) + } + }) + b.Run("time.AppendFormat", func(b *testing.B) { + for i := 0; i < b.N; i++ { + now.AppendFormat(nil, termTimeFormat) + } + }) + var buf = new(bytes.Buffer) + b.Run("time.Custom", func(b *testing.B) { + for i := 0; i < b.N; i++ { + writeTimeTermFormat(buf, now) + buf.Reset() + } + }) +} + +func TestTermTimeFormat(t *testing.T) { + var now = time.Now() + want := now.AppendFormat(nil, termTimeFormat) + var b = new(bytes.Buffer) + writeTimeTermFormat(b, now) + have := b.Bytes() + if !bytes.Equal(have, want) { + t.Errorf("have != want\nhave: %q\nwant: %q\n", have, want) + } +} From 5fb8ebc9ecb226b84181420b9871c5f61cf4f77d Mon Sep 17 00:00:00 2001 From: Delweng Date: Fri, 1 Dec 2023 21:08:52 +0800 Subject: [PATCH 3/3] eth/tracers: tx-level state in debug_traceCall (#28460) --- eth/tracers/api.go | 18 +++++-- eth/tracers/api_test.go | 116 +++++++++++++++++++++++++++++++++++++--- 2 files changed, 125 insertions(+), 9 deletions(-) diff --git a/eth/tracers/api.go b/eth/tracers/api.go index 300d904a99..7c0028601d 100644 --- a/eth/tracers/api.go +++ b/eth/tracers/api.go @@ -164,6 +164,7 @@ type TraceCallConfig struct { TraceConfig StateOverrides *ethapi.StateOverride BlockOverrides *ethapi.BlockOverrides + TxIndex *hexutil.Uint } // StdTraceConfig holds extra parameters to standard-json trace functions. @@ -863,11 +864,17 @@ func (api *API) TraceTransaction(ctx context.Context, hash common.Hash, config * // TraceCall lets you trace a given eth_call. It collects the structured logs // created during the execution of EVM if the given transaction was added on // top of the provided block and returns them as a JSON object. +// If no transaction index is specified, the trace will be conducted on the state +// after executing the specified block. However, if a transaction index is provided, +// the trace will be conducted on the state after executing the specified transaction +// within the specified block. func (api *API) TraceCall(ctx context.Context, args ethapi.TransactionArgs, blockNrOrHash rpc.BlockNumberOrHash, config *TraceCallConfig) (interface{}, error) { // Try to retrieve the specified block var ( - err error - block *types.Block + err error + block *types.Block + statedb *state.StateDB + release StateReleaseFunc ) if hash, ok := blockNrOrHash.Hash(); ok { block, err = api.blockByHash(ctx, hash) @@ -892,7 +899,12 @@ func (api *API) TraceCall(ctx context.Context, args ethapi.TransactionArgs, bloc if config != nil && config.Reexec != nil { reexec = *config.Reexec } - statedb, release, err := api.backend.StateAtBlock(ctx, block, reexec, nil, true, false) + + if config != nil && config.TxIndex != nil { + _, _, statedb, release, err = api.backend.StateAtTransaction(ctx, block, int(*config.TxIndex), reexec) + } else { + statedb, release, err = api.backend.StateAtBlock(ctx, block, reexec, nil, true, false) + } if err != nil { return nil, err } diff --git a/eth/tracers/api_test.go b/eth/tracers/api_test.go index 0f78af9a01..49c3ebb67d 100644 --- a/eth/tracers/api_test.go +++ b/eth/tracers/api_test.go @@ -200,13 +200,51 @@ func TestTraceCall(t *testing.T) { } genBlocks := 10 signer := types.HomesteadSigner{} + nonce := uint64(0) backend := newTestBackend(t, genBlocks, genesis, func(i int, b *core.BlockGen) { // Transfer from account[0] to account[1] // value: 1000 wei // fee: 0 wei - tx, _ := types.SignTx(types.NewTransaction(uint64(i), accounts[1].addr, big.NewInt(1000), params.TxGas, b.BaseFee(), nil), signer, accounts[0].key) + tx, _ := types.SignTx(types.NewTx(&types.LegacyTx{ + Nonce: nonce, + To: &accounts[1].addr, + Value: big.NewInt(1000), + Gas: params.TxGas, + GasPrice: b.BaseFee(), + Data: nil}), + signer, accounts[0].key) b.AddTx(tx) + nonce++ + + if i == genBlocks-2 { + // Transfer from account[0] to account[2] + tx, _ = types.SignTx(types.NewTx(&types.LegacyTx{ + Nonce: nonce, + To: &accounts[2].addr, + Value: big.NewInt(1000), + Gas: params.TxGas, + GasPrice: b.BaseFee(), + Data: nil}), + signer, accounts[0].key) + b.AddTx(tx) + nonce++ + + // Transfer from account[0] to account[1] again + tx, _ = types.SignTx(types.NewTx(&types.LegacyTx{ + Nonce: nonce, + To: &accounts[1].addr, + Value: big.NewInt(1000), + Gas: params.TxGas, + GasPrice: b.BaseFee(), + Data: nil}), + signer, accounts[0].key) + b.AddTx(tx) + nonce++ + } }) + + uintPtr := func(i int) *hexutil.Uint { x := hexutil.Uint(i); return &x } + defer backend.teardown() api := NewAPI(backend) var testSuite = []struct { @@ -240,6 +278,51 @@ func TestTraceCall(t *testing.T) { expectErr: nil, expect: `{"gas":21000,"failed":false,"returnValue":"","structLogs":[]}`, }, + // Upon the last state, default to the post block's state + { + blockNumber: rpc.BlockNumber(genBlocks - 1), + call: ethapi.TransactionArgs{ + From: &accounts[2].addr, + To: &accounts[0].addr, + Value: (*hexutil.Big)(new(big.Int).Add(big.NewInt(params.Ether), big.NewInt(100))), + }, + config: nil, + expect: `{"gas":21000,"failed":false,"returnValue":"","structLogs":[]}`, + }, + // Before the first transaction, should be failed + { + blockNumber: rpc.BlockNumber(genBlocks - 1), + call: ethapi.TransactionArgs{ + From: &accounts[2].addr, + To: &accounts[0].addr, + Value: (*hexutil.Big)(new(big.Int).Add(big.NewInt(params.Ether), big.NewInt(100))), + }, + config: &TraceCallConfig{TxIndex: uintPtr(0)}, + expectErr: fmt.Errorf("tracing failed: insufficient funds for gas * price + value: address %s have 1000000000000000000 want 1000000000000000100", accounts[2].addr), + }, + // Before the target transaction, should be failed + { + blockNumber: rpc.BlockNumber(genBlocks - 1), + call: ethapi.TransactionArgs{ + From: &accounts[2].addr, + To: &accounts[0].addr, + Value: (*hexutil.Big)(new(big.Int).Add(big.NewInt(params.Ether), big.NewInt(100))), + }, + config: &TraceCallConfig{TxIndex: uintPtr(1)}, + expectErr: fmt.Errorf("tracing failed: insufficient funds for gas * price + value: address %s have 1000000000000000000 want 1000000000000000100", accounts[2].addr), + }, + // After the target transaction, should be succeed + { + blockNumber: rpc.BlockNumber(genBlocks - 1), + call: ethapi.TransactionArgs{ + From: &accounts[2].addr, + To: &accounts[0].addr, + Value: (*hexutil.Big)(new(big.Int).Add(big.NewInt(params.Ether), big.NewInt(100))), + }, + config: &TraceCallConfig{TxIndex: uintPtr(2)}, + expectErr: nil, + expect: `{"gas":21000,"failed":false,"returnValue":"","structLogs":[]}`, + }, // Standard JSON trace upon the non-existent block, error expects { blockNumber: rpc.BlockNumber(genBlocks + 1), @@ -297,8 +380,8 @@ func TestTraceCall(t *testing.T) { t.Errorf("test %d: expect error %v, got nothing", i, testspec.expectErr) continue } - if !reflect.DeepEqual(err, testspec.expectErr) { - t.Errorf("test %d: error mismatch, want %v, git %v", i, testspec.expectErr, err) + if !reflect.DeepEqual(err.Error(), testspec.expectErr.Error()) { + t.Errorf("test %d: error mismatch, want '%v', got '%v'", i, testspec.expectErr, err) } } else { if err != nil { @@ -338,7 +421,14 @@ func TestTraceTransaction(t *testing.T) { // Transfer from account[0] to account[1] // value: 1000 wei // fee: 0 wei - tx, _ := types.SignTx(types.NewTransaction(uint64(i), accounts[1].addr, big.NewInt(1000), params.TxGas, b.BaseFee(), nil), signer, accounts[0].key) + tx, _ := types.SignTx(types.NewTx(&types.LegacyTx{ + Nonce: uint64(i), + To: &accounts[1].addr, + Value: big.NewInt(1000), + Gas: params.TxGas, + GasPrice: b.BaseFee(), + Data: nil}), + signer, accounts[0].key) b.AddTx(tx) target = tx.Hash() }) @@ -388,7 +478,14 @@ func TestTraceBlock(t *testing.T) { // Transfer from account[0] to account[1] // value: 1000 wei // fee: 0 wei - tx, _ := types.SignTx(types.NewTransaction(uint64(i), accounts[1].addr, big.NewInt(1000), params.TxGas, b.BaseFee(), nil), signer, accounts[0].key) + tx, _ := types.SignTx(types.NewTx(&types.LegacyTx{ + Nonce: uint64(i), + To: &accounts[1].addr, + Value: big.NewInt(1000), + Gas: params.TxGas, + GasPrice: b.BaseFee(), + Data: nil}), + signer, accounts[0].key) b.AddTx(tx) txHash = tx.Hash() }) @@ -478,7 +575,14 @@ func TestTracingWithOverrides(t *testing.T) { // Transfer from account[0] to account[1] // value: 1000 wei // fee: 0 wei - tx, _ := types.SignTx(types.NewTransaction(uint64(i), accounts[1].addr, big.NewInt(1000), params.TxGas, b.BaseFee(), nil), signer, accounts[0].key) + tx, _ := types.SignTx(types.NewTx(&types.LegacyTx{ + Nonce: uint64(i), + To: &accounts[1].addr, + Value: big.NewInt(1000), + Gas: params.TxGas, + GasPrice: b.BaseFee(), + Data: nil}), + signer, accounts[0].key) b.AddTx(tx) }) defer backend.chain.Stop()