diff --git a/go/common/log/log.go b/go/common/log/log.go index 416e837830..2b33865511 100644 --- a/go/common/log/log.go +++ b/go/common/log/log.go @@ -57,9 +57,9 @@ func New(component string, level int, out string, ctx ...interface{}) gethlog.Lo l := gethlog.New(context...) var s gethlog.Handler if out == SysOut { - s = gethlog.StreamHandler(os.Stdout, gethlog.TerminalFormat(false)) + s = gethlog.StreamHandler(os.Stdout, TenLogFormat()) } else { - s1, err := gethlog.FileHandler(out, gethlog.LogfmtFormat()) + s1, err := gethlog.FileHandler(out, TenLogFormat()) if err != nil { panic(err) } diff --git a/go/common/log/logformat.go b/go/common/log/logformat.go new file mode 100644 index 0000000000..f83107ca26 --- /dev/null +++ b/go/common/log/logformat.go @@ -0,0 +1,324 @@ +package log + +import ( + "bytes" + "fmt" + "math/big" + "reflect" + "strconv" + "strings" + "sync" + "sync/atomic" + "time" + "unicode/utf8" + + gethlog "github.com/ethereum/go-ethereum/log" + "github.com/holiman/uint256" +) + +// IMPORTANT - the utilities and constants in this format class are copied from the geth log package +// (go-ethereum/log/format.go) and modified to suit our needs. Unfortunately geth log format is not configurable +// and implementation is all private so had to duplicate a lot of it. +// +// The code was modified in places to remove things we don't need, e.g. color, but other than that it's identical. + +const ( + timeFormat = "2006-01-02T15:04:05-0700" + termTimeFormat = "01-02|15:04:05.000" + floatFormat = 'f' + termMsgJust = 40 + termCtxMaxPadding = 40 +) + +// locationTrims are trimmed for display to avoid unwieldy log lines. +var locationTrims = []string{ + "github.com/ethereum/go-ethereum/", + "github.com/ten-protocol/go-ten/", +} + +// locationEnabled is an atomic flag controlling whether the terminal formatter +// should append the log locations too when printing entries. +var locationEnabled atomic.Bool + +// locationLength is the maxmimum path length encountered, which all logs are +// padded to aid in alignment. +var locationLength atomic.Uint32 + +// fieldPadding is a global map with maximum field value lengths seen until now +// to allow padding log contexts in a bit smarter way. +var fieldPadding = make(map[string]int) + +// fieldPaddingLock is a global mutex protecting the field padding map. +var fieldPaddingLock sync.RWMutex + +// TenLogFormat - returns a log format that is used by the Ten logger for both console and file logging. +// Note: this is mostly a copy of gethlog.TerminalFormat but putting it here gives us control and +// means we aren't forced to use the shortened hash format +func TenLogFormat() gethlog.Format { + return gethlog.FormatFunc(func(r *gethlog.Record) []byte { + msg := escapeMessage(r.Msg) + + b := &bytes.Buffer{} + lvl := r.Lvl.AlignedString() + if locationEnabled.Load() { + // Log origin printing was requested, format the location path and line number + location := fmt.Sprintf("%+v", r.Call) + for _, prefix := range locationTrims { + location = strings.TrimPrefix(location, prefix) + } + // Maintain the maximum location length for fancyer alignment + align := int(locationLength.Load()) + if align < len(location) { + align = len(location) + locationLength.Store(uint32(align)) + } + padding := strings.Repeat(" ", align-len(location)) + + // Assemble and print the log heading + fmt.Fprintf(b, "%s[%s|%s]%s %s ", lvl, r.Time.Format(termTimeFormat), location, padding, msg) + } else { + fmt.Fprintf(b, "%s[%s] %s ", lvl, r.Time.Format(termTimeFormat), msg) + } + // try to justify the log output for short messages + length := utf8.RuneCountInString(msg) + if len(r.Ctx) > 0 && length < termMsgJust { + b.Write(bytes.Repeat([]byte{' '}, termMsgJust-length)) + } + // print the keys logfmt style + logfmt(b, r.Ctx) + return b.Bytes() + }) +} + +func logfmt(buf *bytes.Buffer, ctx []interface{}) { + for i := 0; i < len(ctx); i += 2 { + if i != 0 { + buf.WriteByte(' ') + } + + k, ok := ctx[i].(string) + v := formatLogfmtValue(ctx[i+1]) + if !ok { + k, v = ErrKey, fmt.Sprintf("%+T is not a string key", ctx[i]) + } else { + k = escapeString(k) + } + + // XXX: we should probably check that all of your key bytes aren't invalid + fieldPaddingLock.RLock() + padding := fieldPadding[k] + fieldPaddingLock.RUnlock() + + length := utf8.RuneCountInString(v) + if padding < length && length <= termCtxMaxPadding { + padding = length + + fieldPaddingLock.Lock() + fieldPadding[k] = padding + fieldPaddingLock.Unlock() + } + buf.WriteString(k) + buf.WriteByte('=') + buf.WriteString(v) + if i < len(ctx)-2 && padding > length { + buf.Write(bytes.Repeat([]byte{' '}, padding-length)) + } + } + buf.WriteByte('\n') +} + +func formatShared(value interface{}) (result interface{}) { + defer func() { + if err := recover(); err != nil { + if v := reflect.ValueOf(value); v.Kind() == reflect.Ptr && v.IsNil() { + result = "nil" + } else { + panic(err) + } + } + }() + + switch v := value.(type) { + case time.Time: + return v.Format(timeFormat) + + case error: + return v.Error() + + case fmt.Stringer: + return v.String() + + default: + return v + } +} + +// formatValue formats a value for serialization +func formatLogfmtValue(value interface{}) string { + if value == nil { + return "nil" + } + + 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 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) + + case *uint256.Int: + // Uint256s get consumed by the Stringer clause, so we need to handle + // them earlier on. + if v == nil { + return "" + } + return formatLogfmtUint256(v) + } + + value = formatShared(value) + switch v := value.(type) { + 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 gethlog.FormatLogfmtInt64(int64(v)) + case int32: + return gethlog.FormatLogfmtInt64(int64(v)) + case int64: + return gethlog.FormatLogfmtInt64(v) + case uint: + return gethlog.FormatLogfmtUint64(uint64(v)) + case uint32: + return gethlog.FormatLogfmtUint64(uint64(v)) + case uint64: + return gethlog.FormatLogfmtUint64(v) + case string: + return escapeString(v) + default: + return escapeString(fmt.Sprintf("%+v", value)) + } +} + +// formatLogfmtBigInt formats n with thousand separators. +func formatLogfmtBigInt(n *big.Int) string { + if n.IsUint64() { + return gethlog.FormatLogfmtUint64(n.Uint64()) + } + if n.IsInt64() { + return gethlog.FormatLogfmtInt64(n.Int64()) + } + + var ( + text = n.String() + 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:]) +} + +// formatLogfmtUint256 formats n with thousand separators. +func formatLogfmtUint256(n *uint256.Int) string { + if n.IsUint64() { + return gethlog.FormatLogfmtUint64(n.Uint64()) + } + 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:]) +} + +// escapeString checks if the provided string needs escaping/quoting, and +// calls strconv.Quote if needed +func escapeString(s string) string { + needsQuoting := false + for _, r := range s { + // We quote everything below " (0x22) and above~ (0x7E), plus equal-sign + if r <= '"' || r > '~' || r == '=' { + needsQuoting = true + break + } + } + if !needsQuoting { + return s + } + return strconv.Quote(s) +} + +// escapeMessage checks if the provided string needs escaping/quoting, similarly +// to escapeString. The difference is that this method is more lenient: it allows +// for spaces and linebreaks to occur without needing quoting. +func escapeMessage(s string) string { + needsQuoting := false + for _, r := range s { + // Allow CR/LF/TAB. This is to make multi-line messages work. + if r == '\r' || r == '\n' || r == '\t' { + continue + } + // We quote everything below (0x20) and above~ (0x7E), + // plus equal-sign + if r < ' ' || r > '~' || r == '=' { + needsQuoting = true + break + } + } + if !needsQuoting { + return s + } + return strconv.Quote(s) +} diff --git a/integration/common/testlog/testlog.go b/integration/common/testlog/testlog.go index 11f7cb0a58..14ca2d0c22 100644 --- a/integration/common/testlog/testlog.go +++ b/integration/common/testlog/testlog.go @@ -45,7 +45,7 @@ func Setup(cfg *Cfg) *os.File { } logFile = f.Name() // hardcode geth log level to error only - gethlog.Root().SetHandler(gethlog.LvlFilterHandler(cfg.LogLevel, gethlog.StreamHandler(f, gethlog.LogfmtFormat()))) + gethlog.Root().SetHandler(gethlog.LvlFilterHandler(cfg.LogLevel, gethlog.StreamHandler(f, log.TenLogFormat()))) testlog = gethlog.Root().New(log.CmpKey, log.TestLogCmp) return f } diff --git a/tools/faucet/faucet/faucet.go b/tools/faucet/faucet/faucet.go index 981fd4dd66..4efb7c6132 100644 --- a/tools/faucet/faucet/faucet.go +++ b/tools/faucet/faucet/faucet.go @@ -13,6 +13,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/log" + tenlog "github.com/ten-protocol/go-ten/go/common/log" "github.com/ten-protocol/go-ten/go/obsclient" "github.com/ten-protocol/go-ten/go/rpc" "github.com/ten-protocol/go-ten/go/wallet" @@ -37,7 +38,7 @@ type Faucet struct { func NewFaucet(rpcURL string, chainID int64, pkString string) (*Faucet, error) { logger := log.New() - logger.SetHandler(log.StreamHandler(os.Stdout, log.TerminalFormat(false))) + logger.SetHandler(log.StreamHandler(os.Stdout, tenlog.TenLogFormat())) w := wallet.NewInMemoryWalletFromConfig(pkString, chainID, logger) obsClient, err := obsclient.DialWithAuth(rpcURL, w, logger) if err != nil { diff --git a/tools/walletextension/common/common.go b/tools/walletextension/common/common.go index 500981fe30..b01d8e1a6a 100644 --- a/tools/walletextension/common/common.go +++ b/tools/walletextension/common/common.go @@ -8,6 +8,7 @@ import ( "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/crypto/ecies" + "github.com/ten-protocol/go-ten/go/common/log" "github.com/ten-protocol/go-ten/go/common/viewingkey" "github.com/ten-protocol/go-ten/go/rpc" @@ -92,7 +93,7 @@ func NewFileLogger() gethlog.Logger { logger := gethlog.New() // Set the handler to the file - logger.SetHandler(gethlog.StreamHandler(file, gethlog.TerminalFormat(false))) + logger.SetHandler(gethlog.StreamHandler(file, log.TenLogFormat())) return logger }