op-chain-ops/script: cleanup and improve console logging (#11629)

op-chain-ops/script/cheatcodes_environment.go

@@ -183,31 +183,26 @@ func (c *CheatCodesPrecompile) Coinbase(addr common.Address) {
 
 // Broadcast_afc98040 implements https://book.getfoundry.sh/cheatcodes/broadcast
 func (c *CheatCodesPrecompile) Broadcast_afc98040() error {
-	c.h.log.Info("broadcasting next call")
 	return c.h.Prank(nil, nil, false, true)
 }
 
 // Broadcast_e6962cdb implements https://book.getfoundry.sh/cheatcodes/broadcast
 func (c *CheatCodesPrecompile) Broadcast_e6962cdb(who common.Address) error {
-	c.h.log.Info("broadcasting next call", "who", who)
 	return c.h.Prank(&who, nil, false, true)
 }
 
 // StartBroadcast_7fb5297f implements https://book.getfoundry.sh/cheatcodes/start-broadcast
 func (c *CheatCodesPrecompile) StartBroadcast_7fb5297f() error {
-	c.h.log.Info("starting repeat-broadcast")
 	return c.h.Prank(nil, nil, true, true)
 }
 
 // StartBroadcast_7fec2a8d implements https://book.getfoundry.sh/cheatcodes/start-broadcast
 func (c *CheatCodesPrecompile) StartBroadcast_7fec2a8d(who common.Address) error {
-	c.h.log.Info("starting repeat-broadcast", "who", who)
 	return c.h.Prank(&who, nil, true, true)
 }
 
 // StopBroadcast implements https://book.getfoundry.sh/cheatcodes/stop-broadcast
 func (c *CheatCodesPrecompile) StopBroadcast() error {
-	c.h.log.Info("stopping repeat-broadcast")
 	return c.h.StopPrank(true)
 }
 

op-chain-ops/script/console.go

 package script
 
 import (
+	"bytes"
+	"fmt"
+	"math/big"
+	"reflect"
+	"strconv"
+	"strings"
+	"text/scanner"
+
 	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/log"
 )
 
+//go:generate go run ./consolegen --abi-txt=console2.txt --out=console2_gen.go
+
 type ConsolePrecompile struct {
 	logger log.Logger
 	sender func() common.Address
 }
 
-func (c *ConsolePrecompile) log(ctx ...any) {
+func (c *ConsolePrecompile) log(args ...any) {
 	sender := c.sender()
+	logger := c.logger.With("sender", sender)
+	if len(args) == 0 {
+		logger.Info("")
+		return
+	}
+	if msg, ok := args[0].(string); ok { // if starting with a string, use it as message. And format with args if needed.
+		logger.Info(consoleFormat(msg, args[1:]...))
+		return
+	} else {
+		logger.Info(consoleFormat("", args...))
+	}
+}
 
-	// Log the sender, since the self-address is always equal to the ConsoleAddr
-	c.logger.With("sender", sender).Info("console", ctx...)
+type stringFormat struct{}
+type numberFormat struct{}
+type objectFormat struct{}
+type integerFormat struct{}
+type exponentialFormat struct {
+	precision int
 }
+type hexadecimalFormat struct{}
 
-//go:generate go run ./consolegen --abi-txt=console2.txt --out=console2_gen.go
+func formatBigInt(x *big.Int, precision int) string {
+	if precision < 0 {
+		precision = len(new(big.Int).Abs(x).String()) - 1
+		return formatBigIntFixedPrecision(x, uint(precision)) + fmt.Sprintf("e%d", precision)
+	}
+	return formatBigIntFixedPrecision(x, uint(precision))
+}
+
+func formatBigIntFixedPrecision(x *big.Int, precision uint) string {
+	prec := new(big.Int).Exp(big.NewInt(10), big.NewInt(int64(precision)), nil)
+	integer, remainder := new(big.Int).QuoRem(x, prec, new(big.Int))
+	if remainder.Sign() != 0 {
+		decimal := fmt.Sprintf("%0"+fmt.Sprintf("%d", precision)+"d",
+			new(big.Int).Abs(remainder))
+		decimal = strings.TrimRight(decimal, "0")
+		return fmt.Sprintf("%d.%s", integer, decimal)
+	} else {
+		return fmt.Sprintf("%d", integer)
+	}
+}
+
+// formatValue formats a value v following the given format-spec.
+func formatValue(v any, spec any) string {
+	switch x := v.(type) {
+	case string:
+		switch spec.(type) {
+		case stringFormat:
+			return x
+		case objectFormat:
+			return fmt.Sprintf("'%s'", v)
+		default:
+			return "NaN"
+		}
+	case bool:
+		switch spec.(type) {
+		case stringFormat:
+			return fmt.Sprintf("%v", x)
+		case objectFormat:
+			return fmt.Sprintf("'%v'", x)
+		case numberFormat:
+			if x {
+				return "1"
+			}
+			return "0"
+		default:
+			return "NaN"
+		}
+	case *big.Int:
+		switch s := spec.(type) {
+		case stringFormat, objectFormat, numberFormat, integerFormat:
+			return fmt.Sprintf("%d", x)
+		case exponentialFormat:
+			return formatBigInt(x, s.precision)
+		case hexadecimalFormat:
+			return (*hexutil.Big)(x).String()
+		default:
+			return fmt.Sprintf("%d", x)
+		}
+	case *ABIInt256:
+		switch s := spec.(type) {
+		case stringFormat, objectFormat, numberFormat, integerFormat:
+			return fmt.Sprintf("%d", (*big.Int)(x))
+		case exponentialFormat:
+			return formatBigInt((*big.Int)(x), s.precision)
+		case hexadecimalFormat:
+			return (*hexutil.Big)(x).String()
+		default:
+			return fmt.Sprintf("%d", (*big.Int)(x))
+		}
+	case common.Address:
+		switch spec.(type) {
+		case stringFormat, hexadecimalFormat:
+			return x.String()
+		case objectFormat:
+			return fmt.Sprintf("'%s'", x)
+		default:
+			return "NaN"
+		}
+	default:
+		if typ := reflect.TypeOf(v); (typ.Kind() == reflect.Array || typ.Kind() == reflect.Slice) &&
+			typ.Elem().Kind() == reflect.Uint8 {
+			switch spec.(type) {
+			case stringFormat, hexadecimalFormat:
+				return fmt.Sprintf("0x%x", v)
+			case objectFormat:
+				return fmt.Sprintf("'0x%x'", v)
+			default:
+				return "NaN"
+			}
+		}
+		return fmt.Sprintf("%v", v)
+	}
+}
+
+// consoleFormat emulates the foundry-flavor of printf, to format console.log data.
+func consoleFormat(fmtMsg string, values ...any) string {
+	var sc scanner.Scanner
+	sc.Init(bytes.NewReader([]byte(fmtMsg)))
+	// default scanner settings are for Go source code parsing. Reset all of that.
+	sc.Whitespace = 0
+	sc.Mode = 0
+	sc.IsIdentRune = func(ch rune, i int) bool {
+		return false
+	}
+
+	nextValue := func() (v any, ok bool) {
+		if len(values) > 0 {
+			v = values[0]
+			values = values[1:]
+			return v, true
+		}
+		return nil, false
+	}
+
+	// Parses a format-spec from a string sequence (excl. the % prefix)
+	// Returns the spec (if any), and the consumed characters (to abort with / fall back to)
+	formatSpecFromChars := func() (spec any, consumed string) {
+		fmtChar := sc.Scan()
+		switch fmtChar {
+		case 's':
+			return stringFormat{}, "s"
+		case 'd':
+			return numberFormat{}, "d"
+		case 'i':
+			return integerFormat{}, "i"
+		case 'o':
+			return objectFormat{}, "o"
+		case 'e':
+			return exponentialFormat{precision: -1}, "e"
+		case 'x':
+			return hexadecimalFormat{}, "x"
+		case scanner.EOF:
+			return nil, ""
+		default:
+			for ; fmtChar != scanner.EOF; fmtChar = sc.Scan() {
+				if fmtChar == 'e' {
+					precision, err := strconv.ParseUint(consumed, 10, 16)
+					consumed += "e"
+					if err != nil {
+						return nil, consumed
+					}
+					return exponentialFormat{precision: int(precision)}, consumed
+				}
+				consumed += string(fmtChar)
+				if !strings.ContainsRune("0123456789", fmtChar) {
+					return nil, consumed
+				}
+			}
+			return nil, consumed
+		}
+	}
+
+	expectFmt := false
+	var out strings.Builder
+	for sc.Peek() != scanner.EOF {
+		if expectFmt {
+			expectFmt = false
+			spec, consumed := formatSpecFromChars()
+			if spec != nil {
+				value, ok := nextValue()
+				if ok {
+					out.WriteString(formatValue(value, spec))
+				} else {
+					// rather than panic with an .expect() like foundry,
+					// just log the original format string
+					out.WriteRune('%')
+					out.WriteString(consumed)
+				}
+			} else {
+				// on parser failure, write '%' and consumed characters
+				out.WriteRune('%')
+				out.WriteString(consumed)
+			}
+		} else {
+			tok := sc.Scan()
+			if tok == '%' {
+				next := sc.Peek()
+				switch next {
+				case '%': // %% formats as "%"
+					out.WriteRune('%')
+				case scanner.EOF:
+					out.WriteRune(tok)
+				default:
+					expectFmt = true
+				}
+			} else {
+				out.WriteRune(tok)
+			}
+		}
+	}
+
+	// for all remaining values, append them to the output
+	for _, v := range values {
+		if out.Len() > 0 {
+			out.WriteRune(' ')
+		}
+		out.WriteString(formatValue(v, stringFormat{}))
+	}
+	return out.String()
+}

op-chain-ops/script/console_test.go

 package script
 
 import (
+	"fmt"
 	"log/slog"
+	"math/big"
 	"math/rand" // nosemgrep
 	"testing"
 
-	"github.com/stretchr/testify/require"
-
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/log"
+	"github.com/stretchr/testify/require"
 
 	"github.com/ethereum-optimism/optimism/op-service/testlog"
 	"github.com/ethereum-optimism/optimism/op-service/testutils"
@@ -50,8 +51,25 @@ func TestConsole(t *testing.T) {
 		})
 	}
 
-	require.NotNil(t, captLog.FindLog(testlog.NewMessageFilter("console")))
-	require.NotNil(t, captLog.FindLog(testlog.NewAttributesFilter("p0", alice.String())))
-	require.NotNil(t, captLog.FindLog(testlog.NewAttributesFilter("p1", bob.String())))
+	require.NotNil(t, captLog.FindLog(testlog.NewMessageFilter(fmt.Sprintf("%s %s", alice, bob))))
 	require.NotNil(t, captLog.FindLog(testlog.NewAttributesFilter("sender", sender.String())))
 }
+
+func TestFormatter(t *testing.T) {
+	got := consoleFormat("hello %d world %x example %3e",
+		big.NewInt(3), big.NewInt(0xc0ffee), big.NewInt(42), big.NewInt(123))
+	require.Equal(t, "hello 3 world 0xc0ffee example 0.042 123", got)
+	require.Equal(t, "4.2", consoleFormat("%8e", big.NewInt(420000000)))
+	require.Equal(t, "foo true bar false", consoleFormat("foo %s bar %s", true, false))
+	require.Equal(t, "foo 1 bar 0", consoleFormat("foo %d bar %d", true, false))
+	require.Equal(t, "sender: "+DefaultSenderAddr.String(),
+		consoleFormat("sender: %s", DefaultSenderAddr))
+	require.Equal(t, "long 0.000000000000000042 number", consoleFormat("long %18e number", big.NewInt(42)))
+	require.Equal(t, "long 4200.000000000000000003 number", consoleFormat("long %18e number",
+		new(big.Int).Add(new(big.Int).Mul(
+			big.NewInt(42),
+			new(big.Int).Exp(big.NewInt(10), big.NewInt(20), nil),
+		), big.NewInt(3))))
+	require.Equal(t, "1.23456e5", consoleFormat("%e", big.NewInt(123456)))
+	require.Equal(t, "-1.23456e5", consoleFormat("%e", (*ABIInt256)(big.NewInt(-123456))))
+}

op-chain-ops/script/consolegen/main.go

@@ -71,7 +71,6 @@ import (
 			if p == "" {
 				continue
 			}
-			out.WriteString(fmt.Sprintf(`"p%d", `, i))
 			out.WriteString(prettyArg(fmt.Sprintf("p%d", i), p))
 			if i != len(params)-1 {
 				out.WriteString(", ")

op-chain-ops/script/prank.go

@@ -78,7 +78,11 @@ func (h *Host) Prank(msgSender *common.Address, txOrigin *common.Address, repeat
 			return errors.New("you have an active prank; broadcasting and pranks are not compatible")
 		}
 	}
-	h.log.Warn("prank", "sender", msgSender)
+	if broadcast {
+		h.log.Debug("starting broadcast", "sender", msgSender, "repeat", repeat)
+	} else {
+		h.log.Debug("starting prank", "sender", msgSender, "repeat", repeat)
+	}
 	cf.Prank = &Prank{
 		Sender:     msgSender,
 		Origin:     txOrigin,
@@ -108,6 +112,11 @@ func (h *Host) StopPrank(broadcast bool) error {
 	if !cf.Prank.Broadcast && broadcast {
 		return errors.New("no broadcast in progress to stop")
 	}
+	if broadcast {
+		h.log.Debug("stopping broadcast")
+	} else {
+		h.log.Debug("stopping prank")
+	}
 	cf.Prank = nil
 	return nil
 }

op-chain-ops/script/script_test.go

@@ -29,9 +29,7 @@ func TestScript(t *testing.T) {
 	input := bytes4("run()")
 	returnData, _, err := h.Call(scriptContext.Sender, addr, input[:], DefaultFoundryGasLimit, uint256.NewInt(0))
 	require.NoError(t, err, "call failed: %x", string(returnData))
-	require.NotNil(t, captLog.FindLog(
-		testlog.NewAttributesFilter("p0", "sender nonce"),
-		testlog.NewAttributesFilter("p1", "1")))
+	require.NotNil(t, captLog.FindLog(testlog.NewMessageFilter("sender nonce 1")))
 
 	require.NoError(t, h.cheatcodes.Precompile.DumpState("noop"))
 	// and a second time, to see if we can revisit the host state.