diff --git a/cmd/beacon-chain/BUILD.bazel b/cmd/beacon-chain/BUILD.bazel index 57dbd4e36..98fab4205 100644 --- a/cmd/beacon-chain/BUILD.bazel +++ b/cmd/beacon-chain/BUILD.bazel @@ -31,6 +31,7 @@ go_library( "//monitoring/journald:go_default_library", "//runtime/debug:go_default_library", "//runtime/fdlimits:go_default_library", + "//runtime/logging/logrus-prefixed-formatter:go_default_library", "//runtime/maxprocs:go_default_library", "//runtime/tos:go_default_library", "//runtime/version:go_default_library", @@ -39,7 +40,6 @@ go_library( "@com_github_joonix_log//:go_default_library", "@com_github_sirupsen_logrus//:go_default_library", "@com_github_urfave_cli_v2//:go_default_library", - "@com_github_x_cray_logrus_prefixed_formatter//:go_default_library", ], ) diff --git a/cmd/beacon-chain/main.go b/cmd/beacon-chain/main.go index 9d7f9d3ed..eac87a1d1 100644 --- a/cmd/beacon-chain/main.go +++ b/cmd/beacon-chain/main.go @@ -27,12 +27,12 @@ import ( "github.com/prysmaticlabs/prysm/monitoring/journald" "github.com/prysmaticlabs/prysm/runtime/debug" "github.com/prysmaticlabs/prysm/runtime/fdlimits" + prefixed "github.com/prysmaticlabs/prysm/runtime/logging/logrus-prefixed-formatter" _ "github.com/prysmaticlabs/prysm/runtime/maxprocs" "github.com/prysmaticlabs/prysm/runtime/tos" "github.com/prysmaticlabs/prysm/runtime/version" "github.com/sirupsen/logrus" "github.com/urfave/cli/v2" - prefixed "github.com/x-cray/logrus-prefixed-formatter" ) var appFlags = []cli.Flag{ diff --git a/cmd/client-stats/BUILD.bazel b/cmd/client-stats/BUILD.bazel index 98928c59b..bdd369121 100644 --- a/cmd/client-stats/BUILD.bazel +++ b/cmd/client-stats/BUILD.bazel @@ -16,11 +16,11 @@ go_library( "//io/logs:go_default_library", "//monitoring/clientstats:go_default_library", "//monitoring/journald:go_default_library", + "//runtime/logging/logrus-prefixed-formatter:go_default_library", "//runtime/version:go_default_library", "@com_github_joonix_log//:go_default_library", "@com_github_sirupsen_logrus//:go_default_library", "@com_github_urfave_cli_v2//:go_default_library", - "@com_github_x_cray_logrus_prefixed_formatter//:go_default_library", ], ) diff --git a/cmd/client-stats/main.go b/cmd/client-stats/main.go index a5167c052..f7a1aad8c 100644 --- a/cmd/client-stats/main.go +++ b/cmd/client-stats/main.go @@ -12,10 +12,10 @@ import ( "github.com/prysmaticlabs/prysm/io/logs" "github.com/prysmaticlabs/prysm/monitoring/clientstats" "github.com/prysmaticlabs/prysm/monitoring/journald" + prefixed "github.com/prysmaticlabs/prysm/runtime/logging/logrus-prefixed-formatter" "github.com/prysmaticlabs/prysm/runtime/version" "github.com/sirupsen/logrus" "github.com/urfave/cli/v2" - prefixed "github.com/x-cray/logrus-prefixed-formatter" ) var appFlags = []cli.Flag{ diff --git a/cmd/validator/BUILD.bazel b/cmd/validator/BUILD.bazel index 999d621e5..8b2e76194 100644 --- a/cmd/validator/BUILD.bazel +++ b/cmd/validator/BUILD.bazel @@ -27,6 +27,7 @@ go_library( "//io/logs:go_default_library", "//monitoring/journald:go_default_library", "//runtime/debug:go_default_library", + "//runtime/logging/logrus-prefixed-formatter:go_default_library", "//runtime/maxprocs:go_default_library", "//runtime/tos:go_default_library", "//runtime/version:go_default_library", @@ -34,7 +35,6 @@ go_library( "@com_github_joonix_log//:go_default_library", "@com_github_sirupsen_logrus//:go_default_library", "@com_github_urfave_cli_v2//:go_default_library", - "@com_github_x_cray_logrus_prefixed_formatter//:go_default_library", ], ) diff --git a/cmd/validator/main.go b/cmd/validator/main.go index 0d361757f..33e39d071 100644 --- a/cmd/validator/main.go +++ b/cmd/validator/main.go @@ -23,13 +23,13 @@ import ( "github.com/prysmaticlabs/prysm/io/logs" "github.com/prysmaticlabs/prysm/monitoring/journald" "github.com/prysmaticlabs/prysm/runtime/debug" + prefixed "github.com/prysmaticlabs/prysm/runtime/logging/logrus-prefixed-formatter" _ "github.com/prysmaticlabs/prysm/runtime/maxprocs" "github.com/prysmaticlabs/prysm/runtime/tos" "github.com/prysmaticlabs/prysm/runtime/version" "github.com/prysmaticlabs/prysm/validator/node" "github.com/sirupsen/logrus" "github.com/urfave/cli/v2" - prefixed "github.com/x-cray/logrus-prefixed-formatter" ) func startNode(ctx *cli.Context) error { diff --git a/go.mod b/go.mod index f9417e5fc..0fc55c70c 100644 --- a/go.mod +++ b/go.mod @@ -47,10 +47,13 @@ require ( github.com/libp2p/go-libp2p-pubsub v0.7.1-0.20220701163738-60cf38003244 github.com/logrusorgru/aurora v2.0.3+incompatible github.com/manifoldco/promptui v0.7.0 + github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b github.com/minio/highwayhash v1.0.1 github.com/minio/sha256-simd v1.0.0 github.com/mohae/deepcopy v0.0.0-20170929034955-c48cc78d4826 github.com/multiformats/go-multiaddr v0.6.0 + github.com/onsi/ginkgo v1.16.5 + github.com/onsi/gomega v1.13.0 github.com/patrickmn/go-cache v2.1.0+incompatible github.com/paulbellamy/ratecounter v0.2.0 github.com/pborman/uuid v1.2.1 @@ -78,7 +81,6 @@ require ( github.com/wealdtech/go-eth2-util v1.6.3 github.com/wealdtech/go-eth2-wallet-encryptor-keystorev4 v1.1.3 github.com/wercker/journalhook v0.0.0-20180428041537-5d0a5ae867b3 - github.com/x-cray/logrus-prefixed-formatter v0.5.2 go.etcd.io/bbolt v1.3.5 go.opencensus.io v0.23.0 go.uber.org/automaxprocs v1.3.0 @@ -175,7 +177,6 @@ require ( github.com/mattn/go-isatty v0.0.14 // indirect github.com/mattn/go-runewidth v0.0.9 // indirect github.com/matttproud/golang_protobuf_extensions v1.0.1 // indirect - github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b // indirect github.com/miekg/dns v1.1.50 // indirect github.com/mikioh/tcpinfo v0.0.0-20190314235526-30a79bb1804b // indirect github.com/mikioh/tcpopt v0.0.0-20190314235656-172688c1accc // indirect @@ -196,7 +197,6 @@ require ( github.com/multiformats/go-varint v0.0.6 // indirect github.com/nxadm/tail v1.4.8 // indirect github.com/olekukonko/tablewriter v0.0.5 // indirect - github.com/onsi/ginkgo v1.16.5 // indirect github.com/opencontainers/runtime-spec v1.0.2 // indirect github.com/opentracing/opentracing-go v1.2.0 // indirect github.com/pbnjay/memory v0.0.0-20210728143218-7b4eea64cf58 // indirect diff --git a/go.sum b/go.sum index 7a7c8860e..7772b1cb2 100644 --- a/go.sum +++ b/go.sum @@ -1361,7 +1361,6 @@ github.com/whyrusleeping/timecache v0.0.0-20160911033111-cfcb2f1abfee h1:lYbXeSv github.com/whyrusleeping/timecache v0.0.0-20160911033111-cfcb2f1abfee/go.mod h1:m2aV4LZI4Aez7dP5PMyVKEHhUyEJ/RjmPEDOpDvudHg= github.com/willf/bitset v1.1.3/go.mod h1:RjeCKbqT1RxIR/KWY6phxZiaY1IyutSBfGjNPySAYV4= github.com/wsddn/go-ecdh v0.0.0-20161211032359-48726bab9208/go.mod h1:IotVbo4F+mw0EzQ08zFqg7pK3FebNXpaMsRy2RT+Ees= -github.com/x-cray/logrus-prefixed-formatter v0.5.2 h1:00txxvfBM9muc0jiLIEAkAcIMJzfthRT6usrui8uGmg= github.com/x-cray/logrus-prefixed-formatter v0.5.2/go.mod h1:2duySbKsL6M18s5GU7VPsoEPHyzalCE06qoARUCeBBE= github.com/xdg/scram v0.0.0-20180814205039-7eeb5667e42c/go.mod h1:lB8K/P019DLNhemzwFU4jHLhdvlE6uDZjXFejJXr49I= github.com/xdg/stringprep v1.0.0/go.mod h1:Jhud4/sHMO4oL310DaZAKk9ZaJ08SJfe+sJh0HrGL1Y= diff --git a/runtime/logging/logrus-prefixed-formatter/BUILD.bazel b/runtime/logging/logrus-prefixed-formatter/BUILD.bazel new file mode 100644 index 000000000..244c3bcf1 --- /dev/null +++ b/runtime/logging/logrus-prefixed-formatter/BUILD.bazel @@ -0,0 +1,29 @@ +load("@prysm//tools/go:def.bzl", "go_library", "go_test") + +go_library( + name = "go_default_library", + srcs = ["formatter.go"], + importpath = "github.com/prysmaticlabs/prysm/runtime/logging/logrus-prefixed-formatter", + visibility = ["//visibility:public"], + deps = [ + "@com_github_mgutz_ansi//:go_default_library", + "@com_github_sirupsen_logrus//:go_default_library", + "@org_golang_x_crypto//ssh/terminal:go_default_library", + ], +) + +go_test( + name = "go_default_test", + srcs = [ + "formatter_test.go", + "logrus_prefixed_formatter_suite_test.go", + ], + deps = [ + ":go_default_library", + "//testing/require:go_default_library", + "@com_github_onsi_ginkgo//:go_default_library", + "@com_github_onsi_gomega//:go_default_library", + "@com_github_pkg_errors//:go_default_library", + "@com_github_sirupsen_logrus//:go_default_library", + ], +) diff --git a/runtime/logging/logrus-prefixed-formatter/LICENSE b/runtime/logging/logrus-prefixed-formatter/LICENSE new file mode 100644 index 000000000..b41cb2380 --- /dev/null +++ b/runtime/logging/logrus-prefixed-formatter/LICENSE @@ -0,0 +1,21 @@ +The MIT License (MIT) + +Copyright (c) 2017 Denis Parchenko + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in all +copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE +SOFTWARE. diff --git a/runtime/logging/logrus-prefixed-formatter/README.md b/runtime/logging/logrus-prefixed-formatter/README.md new file mode 100644 index 000000000..cf15699db --- /dev/null +++ b/runtime/logging/logrus-prefixed-formatter/README.md @@ -0,0 +1,117 @@ +# Logrus Prefixed Log Formatter + +Originally from [github.com/x-cray/logrus-prefixed-formatter(https://github.com/x-cray/logrus-prefixed-formatter) + +[Logrus](https://github.com/sirupsen/logrus) formatter mainly based on original `logrus.TextFormatter` but with slightly +modified colored output and support for log entry prefixes, e.g. message source followed by a colon. In addition, custom +color themes are supported. + +![Formatter screenshot](http://cl.ly/image/1w0B3F233F3z/formatter-screenshot@2x.png) + +Just like with the original `logrus.TextFormatter` when a TTY is not attached, the output is compatible with the +[logfmt](http://godoc.org/github.com/kr/logfmt) format: + +```text +time="Oct 27 00:44:26" level=debug msg="Started observing beach" animal=walrus number=8 +time="Oct 27 00:44:26" level=info msg="A group of walrus emerges from the ocean" animal=walrus size=10 +time="Oct 27 00:44:26" level=warning msg="The group's number increased tremendously!" number=122 omg=true +time="Oct 27 00:44:26" level=debug msg="Temperature changes" temperature=-4 +time="Oct 27 00:44:26" level=panic msg="It's over 9000!" animal=orca size=9009 +time="Oct 27 00:44:26" level=fatal msg="The ice breaks!" number=100 omg=true +exit status 1 +``` + +## Installation +To install formatter, use `go get`: + +```sh +$ go get github.com/prysmaticlabs/prysm/runtime/logging/logrus-prefixed-formatter +``` + +## Usage +Here is how it should be used: + +```go +package main + +import ( + "github.com/sirupsen/logrus" + prefixed "github.com/prysmaticlabs/prysm/runtime/logging/logrus-prefixed-formatter" +) + +var log = logrus.New() + +func init() { + log.Formatter = new(prefixed.TextFormatter) + log.Level = logrus.DebugLevel +} + +func main() { + log.WithFields(logrus.Fields{ + "prefix": "main", + "animal": "walrus", + "number": 8, + }).Debug("Started observing beach") + + log.WithFields(logrus.Fields{ + "prefix": "sensor", + "temperature": -4, + }).Info("Temperature changes") +} +``` + +## API +`prefixed.TextFormatter` exposes the following fields and methods. + +### Fields + +* `ForceColors bool` — set to true to bypass checking for a TTY before outputting colors. +* `DisableColors bool` — force disabling colors. For a TTY colors are enabled by default. +* `DisableUppercase bool` — set to true to turn off the conversion of the log level names to uppercase. +* `ForceFormatting bool` — force formatted layout, even for non-TTY output. +* `DisableTimestamp bool` — disable timestamp logging. Useful when output is redirected to logging system that already adds timestamps. +* `FullTimestamp bool` — enable logging the full timestamp when a TTY is attached instead of just the time passed since beginning of execution. +* `TimestampFormat string` — timestamp format to use for display when a full timestamp is printed. +* `DisableSorting bool` — the fields are sorted by default for a consistent output. For applications that log extremely frequently and don't use the JSON formatter this may not be desired. +* `QuoteEmptyFields bool` — wrap empty fields in quotes if true. +* `QuoteCharacter string` — can be set to the override the default quoting character `"` with something else. For example: `'`, or `` ` ``. +* `SpacePadding int` — pad msg field with spaces on the right for display. The value for this parameter will be the size of padding. Its default value is zero, which means no padding will be applied. + +### Methods + +#### `SetColorScheme(colorScheme *prefixed.ColorScheme)` + +Sets an alternative color scheme for colored output. `prefixed.ColorScheme` struct supports the following fields: +* `InfoLevelStyle string` — info level style. +* `WarnLevelStyle string` — warn level style. +* `ErrorLevelStyle string` — error style. +* `FatalLevelStyle string` — fatal level style. +* `PanicLevelStyle string` — panic level style. +* `DebugLevelStyle string` — debug level style. +* `PrefixStyle string` — prefix style. +* `TimestampStyle string` — timestamp style. + +Color styles should be specified using [mgutz/ansi](https://github.com/mgutz/ansi#style-format) style syntax. For example, here is the default theme: + +```go +InfoLevelStyle: "green", +WarnLevelStyle: "yellow", +ErrorLevelStyle: "red", +FatalLevelStyle: "red", +PanicLevelStyle: "red", +DebugLevelStyle: "blue", +PrefixStyle: "cyan", +TimestampStyle: "black+h" +``` + +It's not necessary to specify all colors when changing color scheme if you want to change just specific ones: + +```go +formatter.SetColorScheme(&prefixed.ColorScheme{ + PrefixStyle: "blue+b", + TimestampStyle: "white+h", +}) +``` + +# License +MIT diff --git a/runtime/logging/logrus-prefixed-formatter/formatter.go b/runtime/logging/logrus-prefixed-formatter/formatter.go new file mode 100644 index 000000000..5523bd343 --- /dev/null +++ b/runtime/logging/logrus-prefixed-formatter/formatter.go @@ -0,0 +1,387 @@ +package prefixed + +import ( + "bytes" + "fmt" + "io" + "os" + "regexp" + "sort" + "strings" + "sync" + "time" + + "github.com/mgutz/ansi" + "github.com/sirupsen/logrus" + "golang.org/x/crypto/ssh/terminal" +) + +const defaultTimestampFormat = time.RFC3339 + +var ( + baseTimestamp time.Time = time.Now() + defaultColorScheme *ColorScheme = &ColorScheme{ + InfoLevelStyle: "green", + WarnLevelStyle: "yellow", + ErrorLevelStyle: "red", + FatalLevelStyle: "red", + PanicLevelStyle: "red", + DebugLevelStyle: "blue", + PrefixStyle: "cyan", + TimestampStyle: "black+h", + } + noColorsColorScheme *compiledColorScheme = &compiledColorScheme{ + InfoLevelColor: ansi.ColorFunc(""), + WarnLevelColor: ansi.ColorFunc(""), + ErrorLevelColor: ansi.ColorFunc(""), + FatalLevelColor: ansi.ColorFunc(""), + PanicLevelColor: ansi.ColorFunc(""), + DebugLevelColor: ansi.ColorFunc(""), + PrefixColor: ansi.ColorFunc(""), + TimestampColor: ansi.ColorFunc(""), + } + defaultCompiledColorScheme *compiledColorScheme = compileColorScheme(defaultColorScheme) +) + +func miniTS() int { + return int(time.Since(baseTimestamp) / time.Second) +} + +type ColorScheme struct { + InfoLevelStyle string + WarnLevelStyle string + ErrorLevelStyle string + FatalLevelStyle string + PanicLevelStyle string + DebugLevelStyle string + PrefixStyle string + TimestampStyle string +} + +type compiledColorScheme struct { + InfoLevelColor func(string) string + WarnLevelColor func(string) string + ErrorLevelColor func(string) string + FatalLevelColor func(string) string + PanicLevelColor func(string) string + DebugLevelColor func(string) string + PrefixColor func(string) string + TimestampColor func(string) string +} + +type TextFormatter struct { + // Set to true to bypass checking for a TTY before outputting colors. + ForceColors bool + + // Whether the logger's out is to a terminal. + isTerminal bool + + // Force disabling colors. For a TTY colors are enabled by default. + DisableColors bool + + // Force formatted layout, even for non-TTY output. + ForceFormatting bool + + // Disable timestamp logging. useful when output is redirected to logging + // system that already adds timestamps. + DisableTimestamp bool + + // Disable the conversion of the log levels to uppercase + DisableUppercase bool + + // Enable logging the full timestamp when a TTY is attached instead of just + // the time passed since beginning of execution. + FullTimestamp bool + + // The fields are sorted by default for a consistent output. For applications + // that log extremely frequently and don't use the JSON formatter this may not + // be desired. + DisableSorting bool + + // Wrap empty fields in quotes if true. + QuoteEmptyFields bool + + sync.Once + + // Pad msg field with spaces on the right for display. + // The value for this parameter will be the size of padding. + // Its default value is zero, which means no padding will be applied for msg. + SpacePadding int + + // Color scheme to use. + colorScheme *compiledColorScheme + + // Can be set to the override the default quoting character " + // with something else. For example: ', or `. + QuoteCharacter string + + // Timestamp format to use for display when a full timestamp is printed. + TimestampFormat string +} + +func getCompiledColor(main string, fallback string) func(string) string { + var style string + if main != "" { + style = main + } else { + style = fallback + } + return ansi.ColorFunc(style) +} + +func compileColorScheme(s *ColorScheme) *compiledColorScheme { + return &compiledColorScheme{ + InfoLevelColor: getCompiledColor(s.InfoLevelStyle, defaultColorScheme.InfoLevelStyle), + WarnLevelColor: getCompiledColor(s.WarnLevelStyle, defaultColorScheme.WarnLevelStyle), + ErrorLevelColor: getCompiledColor(s.ErrorLevelStyle, defaultColorScheme.ErrorLevelStyle), + FatalLevelColor: getCompiledColor(s.FatalLevelStyle, defaultColorScheme.FatalLevelStyle), + PanicLevelColor: getCompiledColor(s.PanicLevelStyle, defaultColorScheme.PanicLevelStyle), + DebugLevelColor: getCompiledColor(s.DebugLevelStyle, defaultColorScheme.DebugLevelStyle), + PrefixColor: getCompiledColor(s.PrefixStyle, defaultColorScheme.PrefixStyle), + TimestampColor: getCompiledColor(s.TimestampStyle, defaultColorScheme.TimestampStyle), + } +} + +func (f *TextFormatter) init(entry *logrus.Entry) { + if len(f.QuoteCharacter) == 0 { + f.QuoteCharacter = "\"" + } + if entry.Logger != nil { + f.isTerminal = f.checkIfTerminal(entry.Logger.Out) + } +} + +func (f *TextFormatter) checkIfTerminal(w io.Writer) bool { + switch v := w.(type) { + case *os.File: + return terminal.IsTerminal(int(v.Fd())) + default: + return false + } +} + +func (f *TextFormatter) SetColorScheme(colorScheme *ColorScheme) { + f.colorScheme = compileColorScheme(colorScheme) +} + +func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { + var b *bytes.Buffer + var keys []string = make([]string, 0, len(entry.Data)) + for k := range entry.Data { + keys = append(keys, k) + } + lastKeyIdx := len(keys) - 1 + + if !f.DisableSorting { + sort.Strings(keys) + } + if entry.Buffer != nil { + b = entry.Buffer + } else { + b = &bytes.Buffer{} + } + + prefixFieldClashes(entry.Data) + + f.Do(func() { f.init(entry) }) + + isFormatted := f.ForceFormatting || f.isTerminal + + timestampFormat := f.TimestampFormat + if timestampFormat == "" { + timestampFormat = defaultTimestampFormat + } + if isFormatted { + isColored := (f.ForceColors || f.isTerminal) && !f.DisableColors + var colorScheme *compiledColorScheme + if isColored { + if f.colorScheme == nil { + colorScheme = defaultCompiledColorScheme + } else { + colorScheme = f.colorScheme + } + } else { + colorScheme = noColorsColorScheme + } + if err := f.printColored(b, entry, keys, timestampFormat, colorScheme); err != nil { + return nil, err + } + } else { + if !f.DisableTimestamp { + if err := f.appendKeyValue(b, "time", entry.Time.Format(timestampFormat), true); err != nil { + return nil, err + } + } + if err := f.appendKeyValue(b, "level", entry.Level.String(), true); err != nil { + return nil, err + } + if entry.Message != "" { + if err := f.appendKeyValue(b, "msg", entry.Message, lastKeyIdx >= 0); err != nil { + return nil, err + } + } + for i, key := range keys { + if err := f.appendKeyValue(b, key, entry.Data[key], lastKeyIdx != i); err != nil { + return nil, err + } + } + } + + if err := b.WriteByte('\n'); err != nil { + return nil, err + } + return b.Bytes(), nil +} + +func (f *TextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys []string, timestampFormat string, colorScheme *compiledColorScheme) (err error) { + var levelColor func(string) string + var levelText string + switch entry.Level { + case logrus.InfoLevel: + levelColor = colorScheme.InfoLevelColor + case logrus.WarnLevel: + levelColor = colorScheme.WarnLevelColor + case logrus.ErrorLevel: + levelColor = colorScheme.ErrorLevelColor + case logrus.FatalLevel: + levelColor = colorScheme.FatalLevelColor + case logrus.PanicLevel: + levelColor = colorScheme.PanicLevelColor + default: + levelColor = colorScheme.DebugLevelColor + } + + if entry.Level != logrus.WarnLevel { + levelText = entry.Level.String() + } else { + levelText = "warn" + } + + if !f.DisableUppercase { + levelText = strings.ToUpper(levelText) + } + + level := levelColor(fmt.Sprintf("%5s", levelText)) + prefix := "" + message := entry.Message + + if prefixValue, ok := entry.Data["prefix"]; ok { + prefix = colorScheme.PrefixColor(" " + prefixValue.(string) + ":") + } else { + prefixValue, trimmedMsg := extractPrefix(entry.Message) + if len(prefixValue) > 0 { + prefix = colorScheme.PrefixColor(" " + prefixValue + ":") + message = trimmedMsg + } + } + + messageFormat := "%s" + if f.SpacePadding != 0 { + messageFormat = fmt.Sprintf("%%-%ds", f.SpacePadding) + } + + if f.DisableTimestamp { + _, err = fmt.Fprintf(b, "%s%s "+messageFormat, level, prefix, message) + } else { + var timestamp string + if !f.FullTimestamp { + timestamp = fmt.Sprintf("[%04d]", miniTS()) + } else { + timestamp = fmt.Sprintf("[%s]", entry.Time.Format(timestampFormat)) + } + _, err = fmt.Fprintf(b, "%s %s%s "+messageFormat, colorScheme.TimestampColor(timestamp), level, prefix, message) + } + for _, k := range keys { + if k != "prefix" { + v := entry.Data[k] + format := " %s=%+v" + if k == logrus.ErrorKey { + format = " %s=%v" // To avoid printing stack traces for errors + } + _, err = fmt.Fprintf(b, format, levelColor(k), v) + } + } + return +} + +func (f *TextFormatter) needsQuoting(text string) bool { + if f.QuoteEmptyFields && len(text) == 0 { + return true + } + for _, ch := range text { + if !((ch >= 'a' && ch <= 'z') || + (ch >= 'A' && ch <= 'Z') || + (ch >= '0' && ch <= '9') || + ch == '-' || ch == '.') { + return true + } + } + return false +} + +func extractPrefix(msg string) (string, string) { + prefix := "" + regex := regexp.MustCompile("^\\[(.*?)\\]") + if regex.MatchString(msg) { + match := regex.FindString(msg) + prefix, msg = match[1:len(match)-1], strings.TrimSpace(msg[len(match):]) + } + return prefix, msg +} + +func (f *TextFormatter) appendKeyValue(b *bytes.Buffer, key string, value interface{}, appendSpace bool) error { + b.WriteString(key) + b.WriteByte('=') + if err := f.appendValue(b, value); err != nil { + return err + } + + if appendSpace { + return b.WriteByte(' ') + } + return nil +} + +func (f *TextFormatter) appendValue(b *bytes.Buffer, value interface{}) (err error) { + switch value := value.(type) { + case string: + if !f.needsQuoting(value) { + _, err = b.WriteString(value) + } else { + _, err = fmt.Fprintf(b, "%s%v%s", f.QuoteCharacter, value, f.QuoteCharacter) + } + case error: + errmsg := value.Error() + if !f.needsQuoting(errmsg) { + _, err = b.WriteString(errmsg) + } else { + _, err = fmt.Fprintf(b, "%s%v%s", f.QuoteCharacter, errmsg, f.QuoteCharacter) + } + default: + _, err = fmt.Fprint(b, value) + } + return +} + +// This is to not silently overwrite `time`, `msg` and `level` fields when +// dumping it. If this code wasn't there doing: +// +// logrus.WithField("level", 1).Info("hello") +// +// would just silently drop the user provided level. Instead with this code +// it'll be logged as: +// +// {"level": "info", "fields.level": 1, "msg": "hello", "time": "..."} +func prefixFieldClashes(data logrus.Fields) { + if t, ok := data["time"]; ok { + data["fields.time"] = t + } + + if m, ok := data["msg"]; ok { + data["fields.msg"] = m + } + + if l, ok := data["level"]; ok { + data["fields.level"] = l + } +} diff --git a/runtime/logging/logrus-prefixed-formatter/formatter_test.go b/runtime/logging/logrus-prefixed-formatter/formatter_test.go new file mode 100644 index 000000000..6b30b00a6 --- /dev/null +++ b/runtime/logging/logrus-prefixed-formatter/formatter_test.go @@ -0,0 +1,73 @@ +package prefixed_test + +import ( + "fmt" + "regexp" + "testing" + + "github.com/pkg/errors" + . "github.com/prysmaticlabs/prysm/runtime/logging/logrus-prefixed-formatter" + "github.com/prysmaticlabs/prysm/testing/require" + + . "github.com/onsi/ginkgo" + . "github.com/onsi/gomega" + "github.com/sirupsen/logrus" +) + +var _ = Describe("Formatter", func() { + var formatter *TextFormatter + var log *logrus.Logger + var output *LogOutput + + BeforeEach(func() { + output = new(LogOutput) + formatter = new(TextFormatter) + log = logrus.New() + log.Out = output + log.Formatter = formatter + log.Level = logrus.DebugLevel + }) + + Describe("logfmt output", func() { + It("should output simple message", func() { + formatter.DisableTimestamp = true + log.Debug("test") + Ω(output.GetValue()).Should(Equal("level=debug msg=test\n")) + }) + + It("should output message with additional field", func() { + formatter.DisableTimestamp = true + log.WithFields(logrus.Fields{"animal": "walrus"}).Debug("test") + Ω(output.GetValue()).Should(Equal("level=debug msg=test animal=walrus\n")) + }) + }) + + Describe("Formatted output", func() { + It("should output formatted message", func() { + formatter.DisableTimestamp = true + formatter.ForceFormatting = true + log.Debug("test") + Ω(output.GetValue()).Should(Equal("DEBUG test\n")) + }) + }) + + Describe("Theming support", func() { + + }) +}) + +func TestFormatter_SuppressErrorStackTraces(t *testing.T) { + formatter := new(TextFormatter) + formatter.ForceFormatting = true + log := logrus.New() + log.Formatter = formatter + output := new(LogOutput) + log.Out = output + + errFn := func() error { + return errors.New("inner") + } + + log.WithError(errors.Wrap(errFn(), "outer")).Error("test") + require.Equal(t, true, regexp.MustCompile(`test error=outer: inner\n\s*$`).MatchString(output.GetValue()), fmt.Sprintf("wrong log output: %s", output.GetValue())) +} diff --git a/runtime/logging/logrus-prefixed-formatter/logrus_prefixed_formatter_suite_test.go b/runtime/logging/logrus-prefixed-formatter/logrus_prefixed_formatter_suite_test.go new file mode 100644 index 000000000..c95894a70 --- /dev/null +++ b/runtime/logging/logrus-prefixed-formatter/logrus_prefixed_formatter_suite_test.go @@ -0,0 +1,26 @@ +package prefixed_test + +import ( + . "github.com/onsi/ginkgo" + . "github.com/onsi/gomega" + + "testing" +) + +type LogOutput struct { + buffer string +} + +func (o *LogOutput) Write(p []byte) (int, error) { + o.buffer += string(p) + return len(p), nil +} + +func (o *LogOutput) GetValue() string { + return o.buffer +} + +func TestLogrusPrefixedFormatter(t *testing.T) { + RegisterFailHandler(Fail) + RunSpecs(t, "LogrusPrefixedFormatter Suite") +} diff --git a/tools/pcli/BUILD.bazel b/tools/pcli/BUILD.bazel index b0ee30280..360b09ca8 100644 --- a/tools/pcli/BUILD.bazel +++ b/tools/pcli/BUILD.bazel @@ -15,12 +15,12 @@ go_library( "//consensus-types/wrapper:go_default_library", "//encoding/ssz/equality:go_default_library", "//proto/prysm/v1alpha1:go_default_library", + "//runtime/logging/logrus-prefixed-formatter:go_default_library", "//runtime/version:go_default_library", "@com_github_kr_pretty//:go_default_library", "@com_github_prysmaticlabs_fastssz//:go_default_library", "@com_github_sirupsen_logrus//:go_default_library", "@com_github_urfave_cli_v2//:go_default_library", - "@com_github_x_cray_logrus_prefixed_formatter//:go_default_library", "@in_gopkg_d4l3k_messagediff_v1//:go_default_library", ], ) diff --git a/tools/pcli/main.go b/tools/pcli/main.go index 55cb89725..42ec7fa96 100644 --- a/tools/pcli/main.go +++ b/tools/pcli/main.go @@ -15,10 +15,10 @@ import ( "github.com/prysmaticlabs/prysm/consensus-types/wrapper" "github.com/prysmaticlabs/prysm/encoding/ssz/equality" ethpb "github.com/prysmaticlabs/prysm/proto/prysm/v1alpha1" + prefixed "github.com/prysmaticlabs/prysm/runtime/logging/logrus-prefixed-formatter" "github.com/prysmaticlabs/prysm/runtime/version" log "github.com/sirupsen/logrus" "github.com/urfave/cli/v2" - prefixed "github.com/x-cray/logrus-prefixed-formatter" "gopkg.in/d4l3k/messagediff.v1" )