refactor: make measurex depend on measurexlite (#892)

This diff makes `measurex` depend on `measurexlite` rather than the other way around.

While there, add unit tests.

Closes https://github.com/ooni/probe/issues/2240

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<string>.
-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

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

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

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

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

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

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 {