From 34dc029b3349faa79860059686b445169ac234bd Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Mon, 5 Sep 2022 10:06:44 +0200 Subject: [PATCH] feat(miniooni): optionally log using emojis (#932) As silly as it seems, emojis help _a lot_ when eyeballing logs to quickly identify unexpected lines. I'm doing this work as part of https://github.com/ooni/probe/issues/2257 --- internal/cmd/miniooni/logging.go | 35 --------- internal/cmd/miniooni/main.go | 13 +++- internal/logx/logx.go | 63 ++++++++++++++++ internal/logx/logx_test.go | 109 ++++++++++++++++++++++++++++ internal/model/mocks/writer.go | 16 ++++ internal/model/mocks/writer_test.go | 25 +++++++ 6 files changed, 225 insertions(+), 36 deletions(-) delete mode 100644 internal/cmd/miniooni/logging.go create mode 100644 internal/logx/logx.go create mode 100644 internal/logx/logx_test.go create mode 100644 internal/model/mocks/writer.go create mode 100644 internal/model/mocks/writer_test.go diff --git a/internal/cmd/miniooni/logging.go b/internal/cmd/miniooni/logging.go deleted file mode 100644 index 69f1e31..0000000 --- a/internal/cmd/miniooni/logging.go +++ /dev/null @@ -1,35 +0,0 @@ -package main - -// -// Logging functionality -// - -import ( - "fmt" - "io" - "time" - - "github.com/apex/log" -) - -// logStartTime is the time when we started logging -var logStartTime = time.Now() - -// logHandler implements the log handler required by github.com/apex/log -type logHandler struct { - // Writer is the underlying writer - io.Writer -} - -var _ log.Handler = &logHandler{} - -// HandleLog implements log.Handler -func (h *logHandler) HandleLog(e *log.Entry) (err error) { - s := fmt.Sprintf("[%14.6f] <%s> %s", time.Since(logStartTime).Seconds(), e.Level, e.Message) - if len(e.Fields) > 0 { - s += fmt.Sprintf(": %+v", e.Fields) - } - s += "\n" - _, err = h.Writer.Write([]byte(s)) - return -} diff --git a/internal/cmd/miniooni/main.go b/internal/cmd/miniooni/main.go index eb7f9f8..52b8010 100644 --- a/internal/cmd/miniooni/main.go +++ b/internal/cmd/miniooni/main.go @@ -15,6 +15,7 @@ import ( "github.com/ooni/probe-cli/v3/internal/engine" "github.com/ooni/probe-cli/v3/internal/humanize" "github.com/ooni/probe-cli/v3/internal/legacy/assetsdir" + "github.com/ooni/probe-cli/v3/internal/logx" "github.com/ooni/probe-cli/v3/internal/model" "github.com/ooni/probe-cli/v3/internal/registry" "github.com/ooni/probe-cli/v3/internal/runtimex" @@ -25,6 +26,7 @@ import ( // Options contains the options you can set from the CLI. type Options struct { Annotations []string + Emoji bool ExtraOptions []string HomeDir string Inputs []string @@ -64,6 +66,13 @@ func main() { "add KEY=VALUE annotation to the report (can be repeated multiple times)", ) + flags.BoolVar( + &globalOptions.Emoji, + "emoji", + false, + "whether to use emojis when logging", + ) + flags.StringVar( &globalOptions.HomeDir, "home", @@ -266,7 +275,9 @@ func MainWithConfiguration(experimentName string, currentOptions *Options) { currentOptions.Proxy = fmt.Sprintf("%s:///", currentOptions.Tunnel) } - logger := &log.Logger{Level: log.InfoLevel, Handler: &logHandler{Writer: os.Stderr}} + logHandler := logx.NewHandlerWithDefaultSettings() + logHandler.Emoji = currentOptions.Emoji + logger := &log.Logger{Level: log.InfoLevel, Handler: logHandler} if currentOptions.Verbose { logger.Level = log.DebugLevel } diff --git a/internal/logx/logx.go b/internal/logx/logx.go new file mode 100644 index 0000000..55bf841 --- /dev/null +++ b/internal/logx/logx.go @@ -0,0 +1,63 @@ +// Package logx contains logging extensions +package logx + +import ( + "fmt" + "io" + "os" + "time" + + "github.com/apex/log" +) + +// Handler implements github.com/apex/log.Handler. +type Handler struct { + // Emoji is OPTIONAL and indicates whether to enable emojis. + Emoji bool + + // Now is the MANDATORY function to compute the current time. + Now func() time.Time + + // StartTime is MANDATORY and indicates when we started logging. + StartTime time.Time + + // Writer is MANDATORY and is the underlying writer. + io.Writer +} + +// NewHandlerWithDefaultSettings creates a new Handler with default settings. +func NewHandlerWithDefaultSettings() *Handler { + return &Handler{ + Emoji: false, + Now: time.Now, + StartTime: time.Now(), + Writer: os.Stderr, + } +} + +var _ log.Handler = &Handler{} + +// HandleLog implements log.Handler +func (h *Handler) HandleLog(e *log.Entry) (err error) { + level := fmt.Sprintf("<%s>", e.Level.String()) + if h.Emoji { + switch e.Level { + case log.DebugLevel: + level = "🧐" + case log.InfoLevel: + level = "🗒️" + case log.WarnLevel: + level = "🔥" + default: + // keep the original string + } + } + elapsed := h.Now().Sub(h.StartTime) + s := fmt.Sprintf("[%14.6f] %s %s", elapsed.Seconds(), level, e.Message) + if len(e.Fields) > 0 { + s += fmt.Sprintf(": %+v", e.Fields) + } + s += "\n" + _, err = h.Writer.Write([]byte(s)) + return +} diff --git a/internal/logx/logx_test.go b/internal/logx/logx_test.go new file mode 100644 index 0000000..4e99aeb --- /dev/null +++ b/internal/logx/logx_test.go @@ -0,0 +1,109 @@ +package logx + +import ( + "fmt" + "os" + "testing" + "time" + + "github.com/apex/log" + "github.com/google/go-cmp/cmp" + "github.com/ooni/probe-cli/v3/internal/model/mocks" + "github.com/ooni/probe-cli/v3/internal/testingx" +) + +func TestNewHandlerWithDefaultSettings(t *testing.T) { + lh := NewHandlerWithDefaultSettings() + if lh.Emoji { + t.Fatal("expected false") + } + // Note: Go does not allow us to check whether lh.Now == time.Now + if lh.StartTime.IsZero() { + t.Fatal("expected non-zero time") + } + if lh.Writer != os.Stderr { + t.Fatal("expected stderr") + } +} + +// creates a new handler with deterministic time to help with testing +func newHandlerForTesting() *Handler { + lh := NewHandlerWithDefaultSettings() + dtime := testingx.NewTimeDeterministic(time.Now()) + lh.Now = dtime.Now + lh.StartTime = dtime.Now() + return lh +} + +func TestLogHandlerHandleLog(t *testing.T) { + type config struct { + // name of the test + Name string + + // whether to use emojis + Emoji bool + + // the verbosity level of the log entry + Level log.Level + + // the string we expect for severity + ExpectSeverity string + } + + configs := []config{{ + Name: "debug level without emoji", + Emoji: false, + Level: log.DebugLevel, + ExpectSeverity: "", + }, { + Name: "info level without emoji", + Emoji: false, + Level: log.InfoLevel, + ExpectSeverity: "", + }, { + Name: "warn level without emoji", + Emoji: false, + Level: log.WarnLevel, + ExpectSeverity: "", + }, { + Name: "debug level with emoji", + Emoji: true, + Level: log.DebugLevel, + ExpectSeverity: "🧐", + }, { + Name: "info level with emoji", + Emoji: true, + Level: log.InfoLevel, + ExpectSeverity: "🗒️", + }, { + Name: "warn level with emoji", + Emoji: true, + Level: log.WarnLevel, + ExpectSeverity: "🔥", + }} + + for _, cnf := range configs { + t.Run(cnf.Name, func(t *testing.T) { + expected := fmt.Sprintf("[ 1.000000] %s antani: map[error:EOF]\n", cnf.ExpectSeverity) + var got string + lh := newHandlerForTesting() + lh.Emoji = cnf.Emoji + lh.Writer = &mocks.Writer{ + MockWrite: func(b []byte) (int, error) { + got = string(b) + return len(b), nil + }, + } + lh.HandleLog(&log.Entry{ + Fields: map[string]any{ + "error": "EOF", + }, + Level: cnf.Level, + Message: "antani", + }) + if diff := cmp.Diff(expected, got); diff != "" { + t.Fatal(diff) + } + }) + } +} diff --git a/internal/model/mocks/writer.go b/internal/model/mocks/writer.go new file mode 100644 index 0000000..d152d7b --- /dev/null +++ b/internal/model/mocks/writer.go @@ -0,0 +1,16 @@ +package mocks + +import "io" + +// Writer allows to mock any io.Writer. +type Writer struct { + MockWrite func(b []byte) (int, error) +} + +// Writer implements an io.Writer. +var _ io.Writer = &Writer{} + +// Write implements io.Writer.Write. +func (r *Writer) Write(b []byte) (int, error) { + return r.MockWrite(b) +} diff --git a/internal/model/mocks/writer_test.go b/internal/model/mocks/writer_test.go new file mode 100644 index 0000000..3d28671 --- /dev/null +++ b/internal/model/mocks/writer_test.go @@ -0,0 +1,25 @@ +package mocks + +import ( + "errors" + "testing" +) + +func TestWriter(t *testing.T) { + t.Run("Write", func(t *testing.T) { + expected := errors.New("mocked error") + r := &Writer{ + MockWrite: func(b []byte) (int, error) { + return 0, expected + }, + } + b := make([]byte, 128) + count, err := r.Write(b) + if !errors.Is(err, expected) { + t.Fatal("unexpected error", err) + } + if count != 0 { + t.Fatal("unexpected count", count) + } + }) +}