From 4a86c542913a2633bc5a9742a0abc703e5f4071e Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Wed, 27 Sep 2023 18:43:04 +0200 Subject: [PATCH] refactor: move scrubbing logger to logx (#1319) This diff is yak shaving for a subsequent diff that attempts to mitigate potential IP addresses leaks caused by using happy eyeballs more aggressively in the codebase. The general idea is that we previously had a netxlite implementation that gave IPv4 preference over IPv6, meaning that we would end up using IPv4 in most cases and very rarely IPv6. As part of my work to make beacons possible, I have introduced happy eyeballs, which means we may sometimes use IPv4 instead of IPv6 if we adopt happy eyeballs more widely. This fact makes it more likely that we include the IPv6 address of a probe when we know its IPv4 address or the other way around into measurements. To mitigate this possible issue before it actually is possible (note that I have not yet changed how we discover the probe IP), I am going to proactively modify the serialization of HTTP bodies and headers to scrub IP endpoints unconditionally. However, to do this, I need to decouple the scrubber package from model such that internal/model/archival.go can use the scrubber package. Part of https://github.com/ooni/probe/issues/2531 --- internal/experiment/tor/tor.go | 3 +- internal/experiment/tor/tor_test.go | 6 +-- internal/logx/scrubber.go | 47 +++++++++++++++++++ .../logger_test.go => logx/scrubber_test.go} | 43 ++++++++--------- internal/scrubber/logger.go | 44 ----------------- 5 files changed, 74 insertions(+), 69 deletions(-) create mode 100644 internal/logx/scrubber.go rename internal/{scrubber/logger_test.go => logx/scrubber_test.go} (67%) delete mode 100644 internal/scrubber/logger.go diff --git a/internal/experiment/tor/tor.go b/internal/experiment/tor/tor.go index 56a429dabc..a03c13100b 100644 --- a/internal/experiment/tor/tor.go +++ b/internal/experiment/tor/tor.go @@ -15,6 +15,7 @@ import ( "github.com/ooni/probe-cli/v3/internal/legacy/measurex" "github.com/ooni/probe-cli/v3/internal/legacy/tracex" + "github.com/ooni/probe-cli/v3/internal/logx" "github.com/ooni/probe-cli/v3/internal/model" "github.com/ooni/probe-cli/v3/internal/netxlite" "github.com/ooni/probe-cli/v3/internal/runtimex" @@ -320,7 +321,7 @@ func maybeScrubbingLogger(input model.Logger, kt keytarget) model.Logger { if !kt.private() { return input } - return &scrubber.Logger{Logger: input} + return &logx.ScrubberLogger{Logger: input} } // defaultFlexibleConnect is the default implementation of the diff --git a/internal/experiment/tor/tor_test.go b/internal/experiment/tor/tor_test.go index 35be66c0aa..db0e7018e9 100644 --- a/internal/experiment/tor/tor_test.go +++ b/internal/experiment/tor/tor_test.go @@ -15,9 +15,9 @@ import ( "github.com/google/go-cmp/cmp" "github.com/ooni/probe-cli/v3/internal/legacy/measurex" "github.com/ooni/probe-cli/v3/internal/legacy/mockable" + "github.com/ooni/probe-cli/v3/internal/logx" "github.com/ooni/probe-cli/v3/internal/model" "github.com/ooni/probe-cli/v3/internal/netxlite" - "github.com/ooni/probe-cli/v3/internal/scrubber" ) func TestNewExperimentMeasurer(t *testing.T) { @@ -717,7 +717,7 @@ func TestMaybeScrubbingLogger(t *testing.T) { if out != input { t.Fatal("not the output we expected") } - if _, ok := out.(*scrubber.Logger); ok { + if _, ok := out.(*logx.ScrubberLogger); ok { t.Fatal("not the output type we expected") } }) @@ -730,7 +730,7 @@ func TestMaybeScrubbingLogger(t *testing.T) { if out == input { t.Fatal("not the output value we expected") } - if _, ok := out.(*scrubber.Logger); !ok { + if _, ok := out.(*logx.ScrubberLogger); !ok { t.Fatal("not the output type we expected") } }) diff --git a/internal/logx/scrubber.go b/internal/logx/scrubber.go new file mode 100644 index 0000000000..b847c7565d --- /dev/null +++ b/internal/logx/scrubber.go @@ -0,0 +1,47 @@ +package logx + +import ( + "fmt" + + "github.com/ooni/probe-cli/v3/internal/model" + "github.com/ooni/probe-cli/v3/internal/scrubber" +) + +// ScrubberLogger is a [model.Logger] with scrubbing. All messages are scrubbed including the ones +// that won't be emitted. As such, this logger is less efficient than a logger without scrubbing. +// +// The zero value is invalid; please init all MANDATORY fields. +type ScrubberLogger struct { + // Logger is the MANDATORY underlying logger to use. + Logger model.Logger +} + +// Debug scrubs and emits a debug message. +func (sl *ScrubberLogger) Debug(message string) { + sl.Logger.Debug(scrubber.Scrub(message)) +} + +// Debugf scrubs, formats, and emits a debug message. +func (sl *ScrubberLogger) Debugf(format string, v ...interface{}) { + sl.Debug(fmt.Sprintf(format, v...)) +} + +// Info scrubs and emits an informational message. +func (sl *ScrubberLogger) Info(message string) { + sl.Logger.Info(scrubber.Scrub(message)) +} + +// Infof scrubs, formats, and emits an informational message. +func (sl *ScrubberLogger) Infof(format string, v ...interface{}) { + sl.Info(fmt.Sprintf(format, v...)) +} + +// Warn scrubs and emits a warning message. +func (sl *ScrubberLogger) Warn(message string) { + sl.Logger.Warn(scrubber.Scrub(message)) +} + +// Warnf scrubs, formats, and emits a warning message. +func (sl *ScrubberLogger) Warnf(format string, v ...interface{}) { + sl.Warn(fmt.Sprintf(format, v...)) +} diff --git a/internal/scrubber/logger_test.go b/internal/logx/scrubber_test.go similarity index 67% rename from internal/scrubber/logger_test.go rename to internal/logx/scrubber_test.go index 1ffad86b85..2e16b455a2 100644 --- a/internal/scrubber/logger_test.go +++ b/internal/logx/scrubber_test.go @@ -1,47 +1,48 @@ -package scrubber +package logx import ( "fmt" "testing" ) -type savingLogger struct { +// scrubberSavingLogger helps writing tests for [ScrubberLogger]. +type scrubberSavingLogger struct { debug []string info []string warn []string } -func (sl *savingLogger) Debug(message string) { +func (sl *scrubberSavingLogger) Debug(message string) { sl.debug = append(sl.debug, message) } -func (sl *savingLogger) Debugf(format string, v ...interface{}) { +func (sl *scrubberSavingLogger) Debugf(format string, v ...interface{}) { sl.Debug(fmt.Sprintf(format, v...)) } -func (sl *savingLogger) Info(message string) { +func (sl *scrubberSavingLogger) Info(message string) { sl.info = append(sl.info, message) } -func (sl *savingLogger) Infof(format string, v ...interface{}) { +func (sl *scrubberSavingLogger) Infof(format string, v ...interface{}) { sl.Info(fmt.Sprintf(format, v...)) } -func (sl *savingLogger) Warn(message string) { +func (sl *scrubberSavingLogger) Warn(message string) { sl.warn = append(sl.warn, message) } -func (sl *savingLogger) Warnf(format string, v ...interface{}) { +func (sl *scrubberSavingLogger) Warnf(format string, v ...interface{}) { sl.Warn(fmt.Sprintf(format, v...)) } -func TestScrubLogger(t *testing.T) { +func TestScrubberLogger(t *testing.T) { input := "failure: 130.192.91.211:443: no route the host" expect := "failure: [scrubbed]: no route the host" t.Run("for debug", func(t *testing.T) { - logger := new(savingLogger) - scrubber := &Logger{Logger: logger} + logger := new(scrubberSavingLogger) + scrubber := &ScrubberLogger{Logger: logger} scrubber.Debug(input) if len(logger.debug) != 1 && len(logger.info) != 0 && len(logger.warn) != 0 { t.Fatal("unexpected number of log lines written") @@ -52,8 +53,8 @@ func TestScrubLogger(t *testing.T) { }) t.Run("for debugf", func(t *testing.T) { - logger := new(savingLogger) - scrubber := &Logger{Logger: logger} + logger := new(scrubberSavingLogger) + scrubber := &ScrubberLogger{Logger: logger} scrubber.Debugf("%s", input) if len(logger.debug) != 1 && len(logger.info) != 0 && len(logger.warn) != 0 { t.Fatal("unexpected number of log lines written") @@ -64,8 +65,8 @@ func TestScrubLogger(t *testing.T) { }) t.Run("for info", func(t *testing.T) { - logger := new(savingLogger) - scrubber := &Logger{Logger: logger} + logger := new(scrubberSavingLogger) + scrubber := &ScrubberLogger{Logger: logger} scrubber.Info(input) if len(logger.debug) != 0 && len(logger.info) != 1 && len(logger.warn) != 0 { t.Fatal("unexpected number of log lines written") @@ -76,8 +77,8 @@ func TestScrubLogger(t *testing.T) { }) t.Run("for infof", func(t *testing.T) { - logger := new(savingLogger) - scrubber := &Logger{Logger: logger} + logger := new(scrubberSavingLogger) + scrubber := &ScrubberLogger{Logger: logger} scrubber.Infof("%s", input) if len(logger.debug) != 0 && len(logger.info) != 1 && len(logger.warn) != 0 { t.Fatal("unexpected number of log lines written") @@ -88,8 +89,8 @@ func TestScrubLogger(t *testing.T) { }) t.Run("for warn", func(t *testing.T) { - logger := new(savingLogger) - scrubber := &Logger{Logger: logger} + logger := new(scrubberSavingLogger) + scrubber := &ScrubberLogger{Logger: logger} scrubber.Warn(input) if len(logger.debug) != 0 && len(logger.info) != 0 && len(logger.warn) != 1 { t.Fatal("unexpected number of log lines written") @@ -100,8 +101,8 @@ func TestScrubLogger(t *testing.T) { }) t.Run("for warnf", func(t *testing.T) { - logger := new(savingLogger) - scrubber := &Logger{Logger: logger} + logger := new(scrubberSavingLogger) + scrubber := &ScrubberLogger{Logger: logger} scrubber.Warnf("%s", input) if len(logger.debug) != 0 && len(logger.info) != 0 && len(logger.warn) != 1 { t.Fatal("unexpected number of log lines written") diff --git a/internal/scrubber/logger.go b/internal/scrubber/logger.go deleted file mode 100644 index 828374ddfa..0000000000 --- a/internal/scrubber/logger.go +++ /dev/null @@ -1,44 +0,0 @@ -package scrubber - -import ( - "fmt" - - "github.com/ooni/probe-cli/v3/internal/model" -) - -// Logger is a Logger with scrubbing. All messages are scrubbed -// including the ones that won't be emitted. As such, this logger -// is less efficient than a logger without scrubbing. -type Logger struct { - model.Logger -} - -// Debug scrubs and emits a debug message. -func (sl *Logger) Debug(message string) { - sl.Logger.Debug(Scrub(message)) -} - -// Debugf scrubs, formats, and emits a debug message. -func (sl *Logger) Debugf(format string, v ...interface{}) { - sl.Debug(fmt.Sprintf(format, v...)) -} - -// Info scrubs and emits an informational message. -func (sl *Logger) Info(message string) { - sl.Logger.Info(Scrub(message)) -} - -// Infof scrubs, formats, and emits an informational message. -func (sl *Logger) Infof(format string, v ...interface{}) { - sl.Info(fmt.Sprintf(format, v...)) -} - -// Warn scrubs and emits a warning message. -func (sl *Logger) Warn(message string) { - sl.Logger.Warn(Scrub(message)) -} - -// Warnf scrubs, formats, and emits a warning message. -func (sl *Logger) Warnf(format string, v ...interface{}) { - sl.Warn(fmt.Sprintf(format, v...)) -}