diff --git a/internal/engine/experiment/tor/tor.go b/internal/engine/experiment/tor/tor.go index 3d3dffa..7cfd44f 100644 --- a/internal/engine/experiment/tor/tor.go +++ b/internal/engine/experiment/tor/tor.go @@ -323,44 +323,11 @@ func (rc *resultsCollector) measureSingleTarget( )) } -// scrubbingLogger is a logger that scrubs endpoints from its output. We are using -// it only here, currently, since we pay some performance penalty in that we evaluate -// the string to be logged regardless of the logging level. -// -// TODO(bassosimone): find a more efficient way of scrubbing logs. -type scrubbingLogger struct { - model.Logger -} - -func (sl scrubbingLogger) Debug(message string) { - sl.Logger.Debug(scrubber.Scrub(message)) -} - -func (sl scrubbingLogger) Debugf(format string, v ...interface{}) { - sl.Debug(fmt.Sprintf(format, v...)) -} - -func (sl scrubbingLogger) Info(message string) { - sl.Logger.Info(scrubber.Scrub(message)) -} - -func (sl scrubbingLogger) Infof(format string, v ...interface{}) { - sl.Info(fmt.Sprintf(format, v...)) -} - -func (sl scrubbingLogger) Warn(message string) { - sl.Logger.Warn(scrubber.Scrub(message)) -} - -func (sl scrubbingLogger) Warnf(format string, v ...interface{}) { - sl.Warn(fmt.Sprintf(format, v...)) -} - func maybeScrubbingLogger(input model.Logger, kt keytarget) model.Logger { if !kt.private() { return input } - return scrubbingLogger{Logger: input} + return &scrubber.Logger{UnderlyingLogger: input} } func (rc *resultsCollector) defaultFlexibleConnect( diff --git a/internal/engine/experiment/tor/tor_test.go b/internal/engine/experiment/tor/tor_test.go index d62490d..d9f4645 100644 --- a/internal/engine/experiment/tor/tor_test.go +++ b/internal/engine/experiment/tor/tor_test.go @@ -18,6 +18,7 @@ import ( "github.com/ooni/probe-cli/v3/internal/engine/mockable" "github.com/ooni/probe-cli/v3/internal/engine/model" "github.com/ooni/probe-cli/v3/internal/engine/netx/errorx" + "github.com/ooni/probe-cli/v3/internal/scrubber" ) func TestNewExperimentMeasurer(t *testing.T) { @@ -704,115 +705,8 @@ func TestMaybeSanitize(t *testing.T) { }) } -type savingLogger struct { - debug []string - info []string - warn []string -} - -func (sl *savingLogger) Debug(message string) { - sl.debug = append(sl.debug, message) -} - -func (sl *savingLogger) Debugf(format string, v ...interface{}) { - sl.Debug(fmt.Sprintf(format, v...)) -} - -func (sl *savingLogger) Info(message string) { - sl.info = append(sl.info, message) -} - -func (sl *savingLogger) Infof(format string, v ...interface{}) { - sl.Info(fmt.Sprintf(format, v...)) -} - -func (sl *savingLogger) Warn(message string) { - sl.warn = append(sl.warn, message) -} - -func (sl *savingLogger) Warnf(format string, v ...interface{}) { - sl.Warn(fmt.Sprintf(format, v...)) -} - -func TestScrubLogger(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 := scrubbingLogger{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") - } - if logger.debug[0] != expect { - t.Fatal("unexpected output written") - } - }) - - t.Run("for debugf", func(t *testing.T) { - logger := new(savingLogger) - scrubber := scrubbingLogger{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") - } - if logger.debug[0] != expect { - t.Fatal("unexpected output written") - } - }) - - t.Run("for info", func(t *testing.T) { - logger := new(savingLogger) - scrubber := scrubbingLogger{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") - } - if logger.info[0] != expect { - t.Fatal("unexpected output written") - } - }) - - t.Run("for infof", func(t *testing.T) { - logger := new(savingLogger) - scrubber := scrubbingLogger{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") - } - if logger.info[0] != expect { - t.Fatal("unexpected output written") - } - }) - - t.Run("for warn", func(t *testing.T) { - logger := new(savingLogger) - scrubber := scrubbingLogger{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") - } - if logger.warn[0] != expect { - t.Fatal("unexpected output written") - } - }) - - t.Run("for warnf", func(t *testing.T) { - logger := new(savingLogger) - scrubber := scrubbingLogger{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") - } - if logger.warn[0] != expect { - t.Fatal("unexpected output written") - } - }) -} - func TestMaybeScrubbingLogger(t *testing.T) { - var input model.Logger = new(savingLogger) + var input model.Logger = log.Log t.Run("for when we don't need to save", func(t *testing.T) { kt := keytarget{target: model.TorTarget{ @@ -822,7 +716,7 @@ func TestMaybeScrubbingLogger(t *testing.T) { if out != input { t.Fatal("not the output we expected") } - if _, ok := out.(*savingLogger); !ok { + if _, ok := out.(*scrubber.Logger); ok { t.Fatal("not the output type we expected") } }) @@ -835,7 +729,7 @@ func TestMaybeScrubbingLogger(t *testing.T) { if out == input { t.Fatal("not the output value we expected") } - if _, ok := out.(scrubbingLogger); !ok { + if _, ok := out.(*scrubber.Logger); !ok { t.Fatal("not the output type we expected") } }) diff --git a/internal/engine/model/logger.go b/internal/engine/model/logger.go index 54cbeae..d44fc4a 100644 --- a/internal/engine/model/logger.go +++ b/internal/engine/model/logger.go @@ -12,7 +12,7 @@ type Logger interface { // Info emits an informational message. Info(msg string) - // Infof format and emits an informational message. + // Infof formats and emits an informational message. Infof(format string, v ...interface{}) // Warn emits a warning message. diff --git a/internal/scrubber/logger.go b/internal/scrubber/logger.go new file mode 100644 index 0000000..813ad44 --- /dev/null +++ b/internal/scrubber/logger.go @@ -0,0 +1,62 @@ +package scrubber + +import "fmt" + +// UnderlyingLogger defines the common interface that a logger should have. It is +// out of the box compatible with `log.Log` in `apex/log`. +type UnderlyingLogger interface { + // Debug emits a debug message. + Debug(msg string) + + // Debugf formats and emits a debug message. + Debugf(format string, v ...interface{}) + + // Info emits an informational message. + Info(msg string) + + // Infof formats and emits an informational message. + Infof(format string, v ...interface{}) + + // Warn emits a warning message. + Warn(msg string) + + // Warnf formats and emits a warning message. + Warnf(format string, v ...interface{}) +} + +// 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 { + UnderlyingLogger +} + +// Debug scrubs and emits a debug message. +func (sl *Logger) Debug(message string) { + sl.UnderlyingLogger.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.UnderlyingLogger.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.UnderlyingLogger.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...)) +} diff --git a/internal/scrubber/logger_test.go b/internal/scrubber/logger_test.go new file mode 100644 index 0000000..a90d760 --- /dev/null +++ b/internal/scrubber/logger_test.go @@ -0,0 +1,113 @@ +package scrubber + +import ( + "fmt" + "testing" +) + +type savingLogger struct { + debug []string + info []string + warn []string +} + +func (sl *savingLogger) Debug(message string) { + sl.debug = append(sl.debug, message) +} + +func (sl *savingLogger) Debugf(format string, v ...interface{}) { + sl.Debug(fmt.Sprintf(format, v...)) +} + +func (sl *savingLogger) Info(message string) { + sl.info = append(sl.info, message) +} + +func (sl *savingLogger) Infof(format string, v ...interface{}) { + sl.Info(fmt.Sprintf(format, v...)) +} + +func (sl *savingLogger) Warn(message string) { + sl.warn = append(sl.warn, message) +} + +func (sl *savingLogger) Warnf(format string, v ...interface{}) { + sl.Warn(fmt.Sprintf(format, v...)) +} + +func TestScrubLogger(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{UnderlyingLogger: 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") + } + if logger.debug[0] != expect { + t.Fatal("unexpected output written") + } + }) + + t.Run("for debugf", func(t *testing.T) { + logger := new(savingLogger) + scrubber := &Logger{UnderlyingLogger: 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") + } + if logger.debug[0] != expect { + t.Fatal("unexpected output written") + } + }) + + t.Run("for info", func(t *testing.T) { + logger := new(savingLogger) + scrubber := &Logger{UnderlyingLogger: 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") + } + if logger.info[0] != expect { + t.Fatal("unexpected output written") + } + }) + + t.Run("for infof", func(t *testing.T) { + logger := new(savingLogger) + scrubber := &Logger{UnderlyingLogger: 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") + } + if logger.info[0] != expect { + t.Fatal("unexpected output written") + } + }) + + t.Run("for warn", func(t *testing.T) { + logger := new(savingLogger) + scrubber := &Logger{UnderlyingLogger: 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") + } + if logger.warn[0] != expect { + t.Fatal("unexpected output written") + } + }) + + t.Run("for warnf", func(t *testing.T) { + logger := new(savingLogger) + scrubber := &Logger{UnderlyingLogger: 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") + } + if logger.warn[0] != expect { + t.Fatal("unexpected output written") + } + }) +}