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

@@ -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
-}

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
 	}

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
+}

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: "<debug>",
+	}, {
+		Name:           "info level without emoji",
+		Emoji:          false,
+		Level:          log.InfoLevel,
+		ExpectSeverity: "<info>",
+	}, {
+		Name:           "warn level without emoji",
+		Emoji:          false,
+		Level:          log.WarnLevel,
+		ExpectSeverity: "<warn>",
+	}, {
+		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)
+			}
+		})
+	}
+}

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)
+}

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)
+		}
+	})
+}