feat(oohelperd): log messages at info level (#896)

We're using a request-specific logger where we also print the ID
of the request. This design helps to observe logs produced by
concurrent requests.

Part of https://github.com/ooni/probe/issues/2183

While there, fix https://github.com/ooni/probe/issues/2241

internal/cmd/oohelperd/dns.go

@@ -9,6 +9,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/ooni/probe-cli/v3/internal/measurexlite"
 	"github.com/ooni/probe-cli/v3/internal/model"
 	"github.com/ooni/probe-cli/v3/internal/netxlite"
 	"github.com/ooni/probe-cli/v3/internal/tracex"
@@ -26,8 +27,11 @@ type dnsConfig struct {
 	// Domain is the MANDATORY domain to resolve.
 	Domain string
 
+	// Logger is the MANDATORY logger to use.
+	Logger model.Logger
+
 	// NewResolver is the MANDATORY factory to create a new resolver.
-	NewResolver func() model.Resolver
+	NewResolver func(model.Logger) model.Resolver
 
 	// Out is the channel where we publish the results.
 	Out chan ctrlDNSResult
@@ -42,9 +46,11 @@ func dnsDo(ctx context.Context, config *dnsConfig) {
 	ctx, cancel := context.WithTimeout(ctx, timeout)
 	defer cancel()
 	defer config.Wg.Done()
-	reso := config.NewResolver()
+	reso := config.NewResolver(config.Logger)
 	defer reso.CloseIdleConnections()
+	ol := measurexlite.NewOperationLogger(config.Logger, "DNSLookup %s", config.Domain)
 	addrs, err := reso.LookupHost(ctx, config.Domain)
+	ol.Stop(err)
 	if addrs == nil {
 		addrs = []string{} // fix: the old test helper did that
 	}

internal/cmd/oohelperd/dns_test.go

@@ -68,7 +68,8 @@ func TestDNSDo(t *testing.T) {
 		ctx := context.Background()
 		config := &dnsConfig{
 			Domain: "antani.ooni.org",
-			NewResolver: func() model.Resolver {
+			Logger: model.DiscardLogger,
+			NewResolver: func(model.Logger) model.Resolver {
 				return &mocks.Resolver{
 					MockLookupHost: func(ctx context.Context, domain string) ([]string, error) {
 						return nil, netxlite.ErrOODNSNoSuchHost

internal/cmd/oohelperd/handler.go

@@ -10,6 +10,7 @@ import (
 	"io"
 	"net/http"
 
+	"github.com/ooni/probe-cli/v3/internal/atomicx"
 	"github.com/ooni/probe-cli/v3/internal/model"
 	"github.com/ooni/probe-cli/v3/internal/netxlite"
 	"github.com/ooni/probe-cli/v3/internal/runtimex"
@@ -18,20 +19,26 @@ import (
 
 // handler implements the Web Connectivity test helper HTTP API.
 type handler struct {
+	// BaseLogger is the MANDATORY logger to use.
+	BaseLogger model.Logger
+
+	// Indexer is the MANDATORY atomic integer used to assign an index to requests.
+	Indexer *atomicx.Int64
+
 	// MaxAcceptableBody is the MANDATORY maximum acceptable response body.
 	MaxAcceptableBody int64
 
 	// NewClient is the MANDATORY factory to create a new HTTPClient.
-	NewClient func() model.HTTPClient
+	NewClient func(model.Logger) model.HTTPClient
 
 	// NewDialer is the MANDATORY factory to create a new Dialer.
-	NewDialer func() model.Dialer
+	NewDialer func(model.Logger) model.Dialer
 
 	// NewResolver is the MANDATORY factory for creating a new resolver.
-	NewResolver func() model.Resolver
+	NewResolver func(model.Logger) model.Resolver
 
 	// NewTLSHandshaker is the MANDATORY factory for creating a new TLS handshaker.
-	NewTLSHandshaker func() model.TLSHandshaker
+	NewTLSHandshaker func(model.Logger) model.TLSHandshaker
 }
 
 var _ http.Handler = &handler{}

internal/cmd/oohelperd/handler_test.go

@@ -10,6 +10,7 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/ooni/probe-cli/v3/internal/atomicx"
 	"github.com/ooni/probe-cli/v3/internal/model"
 	"github.com/ooni/probe-cli/v3/internal/model/mocks"
 	"github.com/ooni/probe-cli/v3/internal/netxlite"
@@ -53,17 +54,19 @@ const requestWithoutDomainName = `{
 
 func TestHandlerWorkingAsIntended(t *testing.T) {
 	handler := &handler{
+		BaseLogger:        model.DiscardLogger,
+		Indexer:           &atomicx.Int64{},
 		MaxAcceptableBody: 1 << 24,
-		NewClient: func() model.HTTPClient {
+		NewClient: func(model.Logger) model.HTTPClient {
 			return http.DefaultClient
 		},
-		NewDialer: func() model.Dialer {
+		NewDialer: func(model.Logger) model.Dialer {
 			return netxlite.NewDialerWithStdlibResolver(model.DiscardLogger)
 		},
-		NewResolver: func() model.Resolver {
+		NewResolver: func(model.Logger) model.Resolver {
 			return netxlite.NewUnwrappedStdlibResolver()
 		},
-		NewTLSHandshaker: func() model.TLSHandshaker {
+		NewTLSHandshaker: func(model.Logger) model.TLSHandshaker {
 			return netxlite.NewTLSHandshakerStdlib(model.DiscardLogger)
 		},
 	}

internal/cmd/oohelperd/http.go

@@ -30,11 +30,14 @@ type httpConfig struct {
 	// Headers is OPTIONAL and contains the request headers we should set.
 	Headers map[string][]string
 
+	// Logger is the MANDATORY logger to use.
+	Logger model.Logger
+
 	// MaxAcceptableBody is MANDATORY and specifies the maximum acceptable body size.
 	MaxAcceptableBody int64
 
 	// NewClient is the MANDATORY factory to create a new client.
-	NewClient func() model.HTTPClient
+	NewClient func(model.Logger) model.HTTPClient
 
 	// Out is the MANDATORY channel where we'll post results.
 	Out chan ctrlHTTPResponse
@@ -48,6 +51,7 @@ type httpConfig struct {
 
 // httpDo performs the HTTP check.
 func httpDo(ctx context.Context, config *httpConfig) {
+	ol := measurexlite.NewOperationLogger(config.Logger, "GET %s", config.URL)
 	const timeout = 15 * time.Second
 	ctx, cancel := context.WithTimeout(ctx, timeout)
 	defer cancel()
@@ -62,6 +66,7 @@ func httpDo(ctx context.Context, config *httpConfig) {
 			Headers:    map[string]string{},
 			StatusCode: -1,
 		}
+		ol.Stop(err)
 		return
 	}
 	// The original test helper failed with extra headers while here
@@ -74,7 +79,7 @@ func httpDo(ctx context.Context, config *httpConfig) {
 			}
 		}
 	}
-	clnt := config.NewClient()
+	clnt := config.NewClient(config.Logger)
 	defer clnt.CloseIdleConnections()
 	resp, err := clnt.Do(req)
 	if err != nil {
@@ -86,6 +91,7 @@ func httpDo(ctx context.Context, config *httpConfig) {
 			Headers:    map[string]string{},
 			StatusCode: -1,
 		}
+		ol.Stop(err)
 		return
 	}
 	defer resp.Body.Close()
@@ -95,6 +101,7 @@ func httpDo(ctx context.Context, config *httpConfig) {
 	}
 	reader := &io.LimitedReader{R: resp.Body, N: config.MaxAcceptableBody}
 	data, err := netxlite.ReadAllContext(ctx, reader)
+	ol.Stop(err)
 	config.Out <- ctrlHTTPResponse{
 		BodyLength: int64(len(data)),
 		Failure:    httpMapFailure(err),

internal/cmd/oohelperd/http_test.go

@@ -20,8 +20,9 @@ func TestHTTPDoWithInvalidURL(t *testing.T) {
 	wg.Add(1)
 	go httpDo(ctx, &httpConfig{
 		Headers:           nil,
+		Logger:            model.DiscardLogger,
 		MaxAcceptableBody: 1 << 24,
-		NewClient: func() model.HTTPClient {
+		NewClient: func(model.Logger) model.HTTPClient {
 			return http.DefaultClient
 		},
 		Out: httpch,
@@ -44,8 +45,9 @@ func TestHTTPDoWithHTTPTransportFailure(t *testing.T) {
 	wg.Add(1)
 	go httpDo(ctx, &httpConfig{
 		Headers:           nil,
+		Logger:            model.DiscardLogger,
 		MaxAcceptableBody: 1 << 24,
-		NewClient: func() model.HTTPClient {
+		NewClient: func(model.Logger) model.HTTPClient {
 			return &http.Client{
 				Transport: &mocks.HTTPTransport{
 					MockRoundTrip: func(req *http.Request) (*http.Response, error) {

internal/cmd/oohelperd/logging.go

@@ -0,0 +1,41 @@
+package main
+
+import "github.com/ooni/probe-cli/v3/internal/model"
+
+// indexLogger is a logger with an index.
+type indexLogger struct {
+	indexstr string
+	logger   model.Logger
+}
+
+var _ model.Logger = &indexLogger{}
+
+// Debug implements DebugLogger.Debug
+func (p *indexLogger) Debug(msg string) {
+	p.logger.Debug(p.indexstr + msg)
+}
+
+// Debugf implements DebugLogger.Debugf
+func (p *indexLogger) Debugf(format string, v ...interface{}) {
+	p.logger.Debugf(p.indexstr+format, v...)
+}
+
+// Info implements InfoLogger.Info
+func (p *indexLogger) Info(msg string) {
+	p.logger.Info(p.indexstr + msg)
+}
+
+// Infov implements InfoLogger.Infov
+func (p *indexLogger) Infof(format string, v ...interface{}) {
+	p.logger.Infof(p.indexstr+format, v...)
+}
+
+// Warn implements Logger.Warn
+func (p *indexLogger) Warn(msg string) {
+	p.logger.Warn(p.indexstr + msg)
+}
+
+// Warnf implements Logger.Warnf
+func (p *indexLogger) Warnf(format string, v ...interface{}) {
+	p.logger.Warnf(p.indexstr+format, v...)
+}

internal/cmd/oohelperd/logging_test.go

@@ -0,0 +1,105 @@
+package main
+
+import (
+	"testing"
+
+	"github.com/ooni/probe-cli/v3/internal/model/mocks"
+)
+
+func TestIndexLogger(t *testing.T) {
+	t.Run("Debug", func(t *testing.T) {
+		expected := "<0>antani"
+		base := &mocks.Logger{
+			MockDebug: func(message string) {
+				if message != expected {
+					t.Fatal("unexpected message")
+				}
+			},
+		}
+		logger := &indexLogger{
+			indexstr: "<0>",
+			logger:   base,
+		}
+		logger.Debug("antani")
+	})
+
+	t.Run("Info", func(t *testing.T) {
+		expected := "<0>antani"
+		base := &mocks.Logger{
+			MockInfo: func(message string) {
+				if message != expected {
+					t.Fatal("unexpected message")
+				}
+			},
+		}
+		logger := &indexLogger{
+			indexstr: "<0>",
+			logger:   base,
+		}
+		logger.Info("antani")
+	})
+
+	t.Run("Warn", func(t *testing.T) {
+		expected := "<0>antani"
+		base := &mocks.Logger{
+			MockWarn: func(message string) {
+				if message != expected {
+					t.Fatal("unexpected message")
+				}
+			},
+		}
+		logger := &indexLogger{
+			indexstr: "<0>",
+			logger:   base,
+		}
+		logger.Warn("antani")
+	})
+
+	t.Run("Debugf", func(t *testing.T) {
+		expected := "<0>antani%d"
+		base := &mocks.Logger{
+			MockDebugf: func(format string, v ...any) {
+				if format != expected {
+					t.Fatal("unexpected message")
+				}
+			},
+		}
+		logger := &indexLogger{
+			indexstr: "<0>",
+			logger:   base,
+		}
+		logger.Debugf("antani%d", 11)
+	})
+
+	t.Run("Infof", func(t *testing.T) {
+		expected := "<0>antani%d"
+		base := &mocks.Logger{
+			MockInfof: func(format string, v ...any) {
+				if format != expected {
+					t.Fatal("unexpected message")
+				}
+			},
+		}
+		logger := &indexLogger{
+			indexstr: "<0>",
+			logger:   base,
+		}
+		logger.Infof("antani%d", 11)
+	})
+
+	t.Run("Warnf", func(t *testing.T) {
+		expected := "<0>antani%d"
+		base := &mocks.Logger{
+			MockWarnf: func(format string, v ...any) {
+				if format != expected {
+					t.Fatal("unexpected message")
+				}
+			},
+		}
+		logger := &indexLogger{
+			indexstr: "<0>",
+			logger:   base,
+		}
+		logger.Warnf("antani%d", 11)
+	})
+}

internal/cmd/oohelperd/main.go

@@ -10,6 +10,7 @@ import (
 	"time"
 
 	"github.com/apex/log"
+	"github.com/ooni/probe-cli/v3/internal/atomicx"
 	"github.com/ooni/probe-cli/v3/internal/model"
 	"github.com/ooni/probe-cli/v3/internal/netxlite"
 	"github.com/ooni/probe-cli/v3/internal/runtimex"
@@ -29,11 +30,11 @@ func init() {
 	srvCtx, srvCancel = context.WithCancel(context.Background())
 }
 
-func newResolver() model.Resolver {
+func newResolver(logger model.Logger) model.Resolver {
 	// Implementation note: pin to a specific resolver so we don't depend upon the
 	// default resolver configured by the box. Also, use an encrypted transport thus
 	// we're less vulnerable to any policy implemented by the box's provider.
-	resolver := netxlite.NewParallelDNSOverHTTPSResolver(log.Log, "https://8.8.8.8/dns-query")
+	resolver := netxlite.NewParallelDNSOverHTTPSResolver(logger, "https://dns.google/dns-query")
 	return resolver
 }
 
@@ -54,16 +55,18 @@ func main() {
 	defer srvCancel()
 	mux := http.NewServeMux()
 	mux.Handle("/", &handler{
+		BaseLogger:        log.Log,
+		Indexer:           &atomicx.Int64{},
 		MaxAcceptableBody: maxAcceptableBody,
-		NewClient: func() model.HTTPClient {
-			return netxlite.NewHTTPClientWithResolver(log.Log, newResolver())
+		NewClient: func(logger model.Logger) model.HTTPClient {
+			return netxlite.NewHTTPClientWithResolver(logger, newResolver(logger))
 		},
-		NewDialer: func() model.Dialer {
-			return netxlite.NewDialerWithResolver(log.Log, newResolver())
+		NewDialer: func(logger model.Logger) model.Dialer {
+			return netxlite.NewDialerWithResolver(logger, newResolver(logger))
 		},
 		NewResolver: newResolver,
-		NewTLSHandshaker: func() model.TLSHandshaker {
-			return netxlite.NewTLSHandshakerStdlib(log.Log)
+		NewTLSHandshaker: func(logger model.Logger) model.TLSHandshaker {
+			return netxlite.NewTLSHandshakerStdlib(logger)
 		},
 	})
 	srv := &http.Server{Addr: *endpoint, Handler: mux}

internal/cmd/oohelperd/measure.go

@@ -6,6 +6,7 @@ package main
 
 import (
 	"context"
+	"fmt"
 	"net"
 	"net/url"
 	"sync"
@@ -24,9 +25,16 @@ type (
 // measure performs the measurement described by the request and
 // returns the corresponding response or an error.
 func measure(ctx context.Context, config *handler, creq *ctrlRequest) (*ctrlResponse, error) {
+	// create indexed logger
+	logger := &indexLogger{
+		indexstr: fmt.Sprintf("<#%d> ", config.Indexer.Add(1)),
+		logger:   config.BaseLogger,
+	}
+
 	// parse input for correctness
 	URL, err := url.Parse(creq.HTTPRequest)
 	if err != nil {
+		logger.Warnf("cannot parse URL: %s", err.Error())
 		return nil, err
 	}
 	wg := &sync.WaitGroup{}
@@ -37,6 +45,7 @@ func measure(ctx context.Context, config *handler, creq *ctrlRequest) (*ctrlResp
 		wg.Add(1)
 		go dnsDo(ctx, &dnsConfig{
 			Domain:      URL.Hostname(),
+			Logger:      logger,
 			NewResolver: config.NewResolver,
 			Out:         dnsch,
 			Wg:          wg,
@@ -78,6 +87,7 @@ func measure(ctx context.Context, config *handler, creq *ctrlRequest) (*ctrlResp
 			Address:          endpoint.Addr,
 			EnableTLS:        endpoint.TLS,
 			Endpoint:         endpoint.Epnt,
+			Logger:           logger,
 			NewDialer:        config.NewDialer,
 			NewTSLHandshaker: config.NewTLSHandshaker,
 			URLHostname:      URL.Hostname(),
@@ -91,6 +101,7 @@ func measure(ctx context.Context, config *handler, creq *ctrlRequest) (*ctrlResp
 	wg.Add(1)
 	go httpDo(ctx, &httpConfig{
 		Headers:           creq.HTTPRequestHeaders,
+		Logger:            logger,
 		MaxAcceptableBody: config.MaxAcceptableBody,
 		NewClient:         config.NewClient,
 		Out:               httpch,

internal/cmd/oohelperd/tcpconnect.go

@@ -47,11 +47,14 @@ type tcpConfig struct {
 	// Endpoint is the MANDATORY endpoint to connect to.
 	Endpoint string
 
+	// Logger is the MANDATORY logger to use.
+	Logger model.Logger
+
 	// NewDialer is the MANDATORY factory for creating a new dialer.
-	NewDialer func() model.Dialer
+	NewDialer func(model.Logger) model.Dialer
 
 	// NewTSLHandshaker is the MANDATORY factory for creating a new handshaker.
-	NewTSLHandshaker func() model.TLSHandshaker
+	NewTSLHandshaker func(model.Logger) model.TLSHandshaker
 
 	// Out is the MANDATORY where we'll post the TCP measurement results.
 	Out chan *tcpResultPair
@@ -78,13 +81,21 @@ func tcpDo(ctx context.Context, config *tcpConfig) {
 	defer func() {
 		config.Out <- out
 	}()
-	dialer := config.NewDialer()
+	ol := measurexlite.NewOperationLogger(
+		config.Logger,
+		"TCPConnect %s EnableTLS=%v SNI=%s",
+		config.Endpoint,
+		config.EnableTLS,
+		config.URLHostname,
+	)
+	dialer := config.NewDialer(config.Logger)
 	defer dialer.CloseIdleConnections()
 	conn, err := dialer.DialContext(ctx, "tcp", config.Endpoint)
 	out.TCP.Failure = tcpMapFailure(newfailure(err))
 	out.TCP.Status = err == nil
 	defer measurexlite.MaybeClose(conn)
 	if err != nil || !config.EnableTLS {
+		ol.Stop(err)
 		return
 	}
 	tlsConfig := &tls.Config{
@@ -92,8 +103,9 @@ func tcpDo(ctx context.Context, config *tcpConfig) {
 		RootCAs:    netxlite.NewDefaultCertPool(),
 		ServerName: config.URLHostname,
 	}
-	thx := config.NewTSLHandshaker()
+	thx := config.NewTSLHandshaker(config.Logger)
 	tlsConn, _, err := thx.Handshake(ctx, conn, tlsConfig)
+	ol.Stop(err)
 	out.TLS = &ctrlTLSResult{
 		ServerName: config.URLHostname,
 		Status:     err == nil,