diff --git a/internal/measurex/failure.go b/internal/measurex/failure.go index b7ddf84..449ab82 100644 --- a/internal/measurex/failure.go +++ b/internal/measurex/failure.go @@ -1,12 +1,6 @@ package measurex -// NewFailure creates a serializable failure from an error. We -// cannot round trip an error using JSON, so we serialize to this -// intermediate format that is a sort of Optional. -func NewFailure(err error) *string { - if err == nil { - return nil - } - s := err.Error() - return &s -} +import "github.com/ooni/probe-cli/v3/internal/measurexlite" + +// NewFailure is an alias for measurexlite.NewFailure +var NewFailure = measurexlite.NewFailure diff --git a/internal/measurex/logger.go b/internal/measurex/logger.go index 5dade55..0a6c832 100644 --- a/internal/measurex/logger.go +++ b/internal/measurex/logger.go @@ -1,63 +1,15 @@ package measurex +import "github.com/ooni/probe-cli/v3/internal/measurexlite" + // // Logger // // Code for logging // -import ( - "fmt" - "sync" - "time" +// NewOperationLogger is an alias for measurex.NewOperationLogger. +var NewOperationLogger = measurexlite.NewOperationLogger - "github.com/ooni/probe-cli/v3/internal/model" -) - -// NewOperationLogger creates a new logger that logs -// about an in-progress operation. -func NewOperationLogger(logger model.Logger, format string, v ...interface{}) *OperationLogger { - ol := &OperationLogger{ - sighup: make(chan interface{}), - logger: logger, - once: &sync.Once{}, - message: fmt.Sprintf(format, v...), - wg: &sync.WaitGroup{}, - } - ol.wg.Add(1) - go ol.logloop() - return ol -} - -// OperationLogger logs about an in-progress operation -type OperationLogger struct { - logger model.Logger - message string - once *sync.Once - sighup chan interface{} - wg *sync.WaitGroup -} - -func (ol *OperationLogger) logloop() { - defer ol.wg.Done() - timer := time.NewTimer(500 * time.Millisecond) - defer timer.Stop() - select { - case <-timer.C: - ol.logger.Infof("%s... in progress", ol.message) - case <-ol.sighup: - // we'll emit directly in stop - } -} - -func (ol *OperationLogger) Stop(err error) { - ol.once.Do(func() { - close(ol.sighup) - ol.wg.Wait() - if err != nil { - ol.logger.Infof("%s... %s", ol.message, err.Error()) - return - } - ol.logger.Infof("%s... ok", ol.message) - }) -} +// OperationLogger is an alias for measurex.OperationLogger. +type OperationLogger = measurexlite.OperationLogger diff --git a/internal/measurexlite/failure.go b/internal/measurexlite/failure.go new file mode 100644 index 0000000..ab83a2b --- /dev/null +++ b/internal/measurexlite/failure.go @@ -0,0 +1,37 @@ +package measurexlite + +import ( + "errors" + + "github.com/ooni/probe-cli/v3/internal/netxlite" + "github.com/ooni/probe-cli/v3/internal/runtimex" +) + +// NewFailure creates an OONI failure from an error. If the error is nil, +// we return nil. If the error is not already an ErrWrapper, it's converted +// to an ErrWrapper. If the ErrWrapper's Failure is not empty, we return its +// string representation. Otherwise we return a string indicating that +// an ErrWrapper has an empty failure (should not happen). +// +// See https://github.com/ooni/spec/blob/master/data-formats/df-007-errors.md +// for more information about OONI failures. +func NewFailure(err error) *string { + if err == nil { + return nil + } + // The following code guarantees that the error is always wrapped even + // when we could not actually hit our code that does the wrapping. A case + // in which this could happen is with context deadline for HTTP when you + // have wrapped the underlying dialers but not the Transport. + var errWrapper *netxlite.ErrWrapper + if !errors.As(err, &errWrapper) { + err := netxlite.NewTopLevelGenericErrWrapper(err) + couldConvert := errors.As(err, &errWrapper) + runtimex.PanicIfFalse(couldConvert, "we should have an ErrWrapper here") + } + s := errWrapper.Failure + if s == "" { + s = "unknown_failure: errWrapper.Failure is empty" + } + return &s +} diff --git a/internal/measurexlite/failure_test.go b/internal/measurexlite/failure_test.go new file mode 100644 index 0000000..ba6012b --- /dev/null +++ b/internal/measurexlite/failure_test.go @@ -0,0 +1,82 @@ +package measurexlite + +import ( + "errors" + "io" + "testing" + + "github.com/ooni/probe-cli/v3/internal/netxlite" +) + +func TestNewFailure(t *testing.T) { + type args struct { + err error + } + tests := []struct { + name string + args args + want *string + }{{ + name: "when error is nil", + args: args{ + err: nil, + }, + want: nil, + }, { + name: "when error is wrapped and failure meaningful", + args: args{ + err: &netxlite.ErrWrapper{ + Failure: netxlite.FailureConnectionRefused, + }, + }, + want: func() *string { + s := netxlite.FailureConnectionRefused + return &s + }(), + }, { + name: "when error is wrapped and failure is not meaningful", + args: args{ + err: &netxlite.ErrWrapper{}, + }, + want: func() *string { + s := "unknown_failure: errWrapper.Failure is empty" + return &s + }(), + }, { + name: "when error is not wrapped but wrappable", + args: args{err: io.EOF}, + want: func() *string { + s := "eof_error" + return &s + }(), + }, { + name: "when the error is not wrapped and not wrappable", + args: args{ + err: errors.New("use of closed socket 127.0.0.1:8080->10.0.0.1:22"), + }, + want: func() *string { + s := "unknown_failure: use of closed socket [scrubbed]->[scrubbed]" + return &s + }(), + }} + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := NewFailure(tt.args.err) + if tt.want == nil && got == nil { + return + } + if tt.want == nil && got != nil { + t.Errorf("NewFailure: want %+v, got %s", tt.want, *got) + return + } + if tt.want != nil && got == nil { + t.Errorf("NewFailure: want %s, got %+v", *tt.want, got) + return + } + if *tt.want != *got { + t.Errorf("NewFailure: want %s, got %s", *tt.want, *got) + return + } + }) + } +} diff --git a/internal/measurexlite/logger.go b/internal/measurexlite/logger.go index 1729346..53cecf4 100644 --- a/internal/measurexlite/logger.go +++ b/internal/measurexlite/logger.go @@ -4,13 +4,71 @@ package measurexlite // Logging support // -import "github.com/ooni/probe-cli/v3/internal/measurex" +import ( + "fmt" + "sync" + "time" -// TODO(bassosimone): we should eventually remove measurex and -// move the logging code from measurex to this package. + "github.com/ooni/probe-cli/v3/internal/model" +) -// NewOperationLogger is an alias for measurex.NewOperationLogger. -var NewOperationLogger = measurex.NewOperationLogger +// NewOperationLogger creates a new logger that logs +// about an in-progress operation. If it takes too much +// time to emit the result of the operation, the code +// will emit an interim log message mentioning that the +// operation is currently in progress. +func NewOperationLogger(logger model.Logger, format string, v ...any) *OperationLogger { + return newOperationLogger(500*time.Millisecond, logger, format, v...) +} -// OperationLogger is an alias for measurex.OperationLogger. -type OperationLogger = measurex.OperationLogger +func newOperationLogger(maxwait time.Duration, logger model.Logger, format string, v ...any) *OperationLogger { + ol := &OperationLogger{ + logger: logger, + maxwait: maxwait, + message: fmt.Sprintf(format, v...), + once: &sync.Once{}, + sighup: make(chan any), + wg: &sync.WaitGroup{}, + } + ol.wg.Add(1) + go ol.maybeEmitProgress() + return ol +} + +// OperationLogger keeps state required to log about an in-progress +// operation as documented by [NewOperationLogger]. +type OperationLogger struct { + logger model.Logger + maxwait time.Duration + message string + once *sync.Once + sighup chan any + wg *sync.WaitGroup +} + +func (ol *OperationLogger) maybeEmitProgress() { + defer ol.wg.Done() + timer := time.NewTimer(ol.maxwait) + defer timer.Stop() + select { + case <-timer.C: + ol.logger.Infof("%s... in progress", ol.message) + case <-ol.sighup: + // we'll emit directly in stop + } +} + +// Stop must be called when the operation is done. The [err] argument +// is the result of the operation, which may be nil. This method ensures +// that we log the final result of the now-completed operation. +func (ol *OperationLogger) Stop(err error) { + ol.once.Do(func() { + close(ol.sighup) + ol.wg.Wait() + if err != nil { + ol.logger.Infof("%s... %s", ol.message, err.Error()) + return + } + ol.logger.Infof("%s... ok", ol.message) + }) +} diff --git a/internal/measurexlite/logger_test.go b/internal/measurexlite/logger_test.go new file mode 100644 index 0000000..bd718c5 --- /dev/null +++ b/internal/measurexlite/logger_test.go @@ -0,0 +1,115 @@ +package measurexlite + +import ( + "fmt" + "io" + "sync" + "testing" + "time" + + "github.com/ooni/probe-cli/v3/internal/model/mocks" +) + +func TestNewOperationLogger(t *testing.T) { + t.Run("for short operation and no error", func(t *testing.T) { + var ( + lines []string + mu sync.Mutex + ) + logger := &mocks.Logger{ + MockInfof: func(format string, v ...interface{}) { + line := fmt.Sprintf(format, v...) + mu.Lock() + lines = append(lines, line) + mu.Unlock() + }, + } + ol := NewOperationLogger(logger, "antani%d", 0) + ol.Stop(nil) + if len(lines) != 1 { + t.Fatal("unexpected number of lines") + } + if lines[0] != "antani0... ok" { + t.Fatal("unexpected first line", lines[0]) + } + }) + + t.Run("for short operation and error", func(t *testing.T) { + var ( + lines []string + mu sync.Mutex + ) + logger := &mocks.Logger{ + MockInfof: func(format string, v ...interface{}) { + line := fmt.Sprintf(format, v...) + mu.Lock() + lines = append(lines, line) + mu.Unlock() + }, + } + ol := NewOperationLogger(logger, "antani%d", 0) + ol.Stop(io.EOF) + if len(lines) != 1 { + t.Fatal("unexpected number of lines") + } + if lines[0] != "antani0... EOF" { + t.Fatal("unexpected first line", lines[0]) + } + }) + + t.Run("for longer operation and no error", func(t *testing.T) { + var ( + lines []string + mu sync.Mutex + ) + logger := &mocks.Logger{ + MockInfof: func(format string, v ...interface{}) { + line := fmt.Sprintf(format, v...) + mu.Lock() + lines = append(lines, line) + mu.Unlock() + }, + } + const maxwait = 100 * time.Microsecond + ol := newOperationLogger(maxwait, logger, "antani%d", 0) + time.Sleep(4 * ol.maxwait) + ol.Stop(nil) + if len(lines) != 2 { + t.Fatal("unexpected number of lines") + } + if lines[0] != "antani0... in progress" { + t.Fatal("unexpected first line", lines[0]) + } + if lines[1] != "antani0... ok" { + t.Fatal("unexpected first line", lines[0]) + } + }) + + t.Run("for longer operation and error", func(t *testing.T) { + var ( + lines []string + mu sync.Mutex + ) + logger := &mocks.Logger{ + MockInfof: func(format string, v ...interface{}) { + line := fmt.Sprintf(format, v...) + mu.Lock() + lines = append(lines, line) + mu.Unlock() + }, + } + const maxwait = 100 * time.Microsecond + ol := newOperationLogger(maxwait, logger, "antani%d", 0) + time.Sleep(4 * ol.maxwait) + ol.Stop(io.EOF) + if len(lines) != 2 { + t.Fatal("unexpected number of lines") + } + if lines[0] != "antani0... in progress" { + t.Fatal("unexpected first line", lines[0]) + } + if lines[1] != "antani0... EOF" { + t.Fatal("unexpected first line", lines[0]) + } + }) +} diff --git a/internal/tracex/archival.go b/internal/tracex/archival.go index a55f483..ec2758c 100644 --- a/internal/tracex/archival.go +++ b/internal/tracex/archival.go @@ -72,6 +72,9 @@ func NewTCPConnectList(begin time.Time, events []Event) (out []TCPConnectEntry) return } +// TODO(bassosimone): can we use measurexlite.NewFailure here? Do we need to have +// a string (as opposed to *string) representation of failures here? + // NewFailure creates a failure nullable string from the given error. This function // is equivalent to NewFailureStr(err).ToFailure(). func NewFailure(err error) *string {