fix(ooniprobe): make sure we actually run echcheck (#1358)

While there, emit some logs while running it.

While there, make the warning emitted when a nettest is disabled much
more specific and informative for the user.

Part of ooni/probe#2547

Part of ooni/probe#2553

cmd/ooniprobe/internal/nettests/echcheck.go

@@ -9,6 +9,7 @@ func (n ECHCheck) Run(ctl *Controller) error {
 	if err != nil {
 		return err
 	}
-	// providing empty input causes the experiment to use the default URL
-	return ctl.Run(builder, []string{})
+	// providing an input containing an empty string causes the experiment
+	// to recognize the empty string and use the default URL
+	return ctl.Run(builder, []string{""})
 }

internal/experiment/echcheck/handshake.go

@@ -8,6 +8,7 @@ import (
 	"time"
 
 	"github.com/apex/log"
+	"github.com/ooni/probe-cli/v3/internal/logx"
 	"github.com/ooni/probe-cli/v3/internal/measurexlite"
 	"github.com/ooni/probe-cli/v3/internal/model"
 	"github.com/ooni/probe-cli/v3/internal/netxlite"
@@ -16,11 +17,13 @@ import (
 
 const echExtensionType uint16 = 0xfe0d
 
-func handshake(ctx context.Context, conn net.Conn, zeroTime time.Time, address string, sni string) *model.ArchivalTLSOrQUICHandshakeResult {
-	return handshakeWithExtension(ctx, conn, zeroTime, address, sni, []utls.TLSExtension{})
+func handshake(ctx context.Context, conn net.Conn, zeroTime time.Time,
+	address string, sni string, logger model.Logger) *model.ArchivalTLSOrQUICHandshakeResult {
+	return handshakeWithExtension(ctx, conn, zeroTime, address, sni, []utls.TLSExtension{}, logger)
 }
 
-func handshakeWithEch(ctx context.Context, conn net.Conn, zeroTime time.Time, address string, sni string) *model.ArchivalTLSOrQUICHandshakeResult {
+func handshakeWithEch(ctx context.Context, conn net.Conn, zeroTime time.Time,
+	address string, sni string, logger model.Logger) *model.ArchivalTLSOrQUICHandshakeResult {
 	payload, err := generateGreaseExtension(rand.Reader)
 	if err != nil {
 		panic("failed to generate grease ECH: " + err.Error())
@@ -31,18 +34,28 @@ func handshakeWithEch(ctx context.Context, conn net.Conn, zeroTime time.Time, ad
 	utlsEchExtension.Id = echExtensionType
 	utlsEchExtension.Data = payload
 
-	return handshakeWithExtension(ctx, conn, zeroTime, address, sni, []utls.TLSExtension{&utlsEchExtension})
+	return handshakeWithExtension(ctx, conn, zeroTime, address, sni, []utls.TLSExtension{&utlsEchExtension}, logger)
 }
 
-func handshakeWithExtension(ctx context.Context, conn net.Conn, zeroTime time.Time, address string, sni string, extensions []utls.TLSExtension) *model.ArchivalTLSOrQUICHandshakeResult {
+func handshakeMaybePrintECH(doprint bool) string {
+	if doprint {
+		return "WithECH"
+	}
+	return ""
+}
+
+func handshakeWithExtension(ctx context.Context, conn net.Conn, zeroTime time.Time, address string, sni string,
+	extensions []utls.TLSExtension, logger model.Logger) *model.ArchivalTLSOrQUICHandshakeResult {
 	tlsConfig := genTLSConfig(sni)
 
 	handshakerConstructor := newHandshakerWithExtensions(extensions)
 	tracedHandshaker := handshakerConstructor(log.Log, &utls.HelloFirefox_Auto)
 
+	ol := logx.NewOperationLogger(logger, "echcheck: TLSHandshake%s", handshakeMaybePrintECH(len(extensions) > 0))
 	start := time.Now()
 	maybeTLSConn, err := tracedHandshaker.Handshake(ctx, conn, tlsConfig)
 	finish := time.Now()
+	ol.Stop(err)
 
 	connState := netxlite.MaybeTLSConnectionState(maybeTLSConn)
 	return measurexlite.NewArchivalTLSOrQUICHandshakeResult(0, start.Sub(zeroTime), "tcp", address, tlsConfig,

internal/experiment/echcheck/handshake_test.go

@@ -9,6 +9,8 @@ import (
 	"net/url"
 	"testing"
 	"time"
+
+	"github.com/ooni/probe-cli/v3/internal/model"
 )
 
 func TestHandshake(t *testing.T) {
@@ -31,7 +33,7 @@ func TestHandshake(t *testing.T) {
 		t.Fatal(err)
 	}
 
-	result := handshakeWithEch(ctx, conn, time.Now(), parsed.Host, "crypto.cloudflare.com")
+	result := handshakeWithEch(ctx, conn, time.Now(), parsed.Host, "crypto.cloudflare.com", model.DiscardLogger)
 	if result == nil {
 		t.Fatal("expected result")
 	}

internal/experiment/echcheck/measure.go

@@ -7,6 +7,7 @@ import (
 	"net/url"
 	"time"
 
+	"github.com/ooni/probe-cli/v3/internal/logx"
 	"github.com/ooni/probe-cli/v3/internal/measurexlite"
 	"github.com/ooni/probe-cli/v3/internal/model"
 	"github.com/ooni/probe-cli/v3/internal/netxlite"
@@ -65,23 +66,29 @@ func (m *Measurer) Run(
 	}
 
 	// 1. perform a DNSLookup
+	ol := logx.NewOperationLogger(args.Session.Logger(), "echcheck: DNSLookup[%s] %s", m.config.resolverURL(), parsed.Host)
 	trace := measurexlite.NewTrace(0, args.Measurement.MeasurementStartTimeSaved)
 	resolver := trace.NewParallelDNSOverHTTPSResolver(args.Session.Logger(), m.config.resolverURL())
 	addrs, err := resolver.LookupHost(ctx, parsed.Host)
+	ol.Stop(err)
 	if err != nil {
 		return err
 	}
 	runtimex.Assert(len(addrs) > 0, "expected at least one entry in addrs")
 	address := net.JoinHostPort(addrs[0], "443")
 
 	// 2. Set up TCP connections
+	ol = logx.NewOperationLogger(args.Session.Logger(), "echcheck: TCPConnect#1 %s", address)
 	var dialer net.Dialer
 	conn, err := dialer.DialContext(ctx, "tcp", address)
+	ol.Stop(err)
 	if err != nil {
 		return netxlite.NewErrWrapper(netxlite.ClassifyGenericError, netxlite.ConnectOperation, err)
 	}
 
+	ol = logx.NewOperationLogger(args.Session.Logger(), "echcheck: TCPConnect#2 %s", address)
 	conn2, err := dialer.DialContext(ctx, "tcp", address)
+	ol.Stop(err)
 	if err != nil {
 		return netxlite.NewErrWrapper(netxlite.ClassifyGenericError, netxlite.ConnectOperation, err)
 	}
@@ -93,11 +100,25 @@ func (m *Measurer) Run(
 	defer cancel()
 
 	go func() {
-		controlChannel <- *handshake(ctx, conn, args.Measurement.MeasurementStartTimeSaved, address, parsed.Host)
+		controlChannel <- *handshake(
+			ctx,
+			conn,
+			args.Measurement.MeasurementStartTimeSaved,
+			address,
+			parsed.Host,
+			args.Session.Logger(),
+		)
 	}()
 
 	go func() {
-		targetChannel <- *handshakeWithEch(ctx, conn2, args.Measurement.MeasurementStartTimeSaved, address, parsed.Host)
+		targetChannel <- *handshakeWithEch(
+			ctx,
+			conn2,
+			args.Measurement.MeasurementStartTimeSaved,
+			address,
+			parsed.Host,
+			args.Session.Logger(),
+		)
 	}()
 
 	control := <-controlChannel

internal/registry/factory.go

@@ -227,10 +227,36 @@ var ErrNoSuchExperiment = errors.New("no such experiment")
 // not enabled by the most recent check-in API call.
 var ErrRequiresForceEnable = errors.New("experiment not enabled by check-in API")
 
-const experimentDisabledByCheckInWarning = `experiment '%s' is not enabled by default and the
-most recent check-in API call did not enable this experiment as well. You can bypass this restriction
-by setting the OONI_FORCE_ENABLE_EXPERIMENT environment variable to the string "1". On Unix like
-systems, you can use 'export OONI_FORCE_ENABLE_EXPERIMENT=1' to set this environment variable.`
+const experimentDisabledByCheckInWarning = `We disabled the '%s' nettest. This usually happens in these cases:
+
+1. we just added the nettest to ooniprobe and we have not enabled it yet;
+
+2. the nettest is flaky and we are working on a fix;
+
+3. you ran Web Connectivity more than 24h ago, hence your check-in cache is stale.
+
+The last case is a known limitation in ooniprobe 3.19 that we will fix in a subsequent
+release of ooniprobe by changing the nettests startup logic.
+
+If you really want to run this nettest, there is a way forward. You need to set the
+OONI_FORCE_ENABLE_EXPERIMENT=1 environment variable. On a Unix like system, use:
+
+    export OONI_FORCE_ENABLE_EXPERIMENT=1
+
+on Windows use:
+
+    set OONI_FORCE_ENABLE_EXPERIMENT=1
+
+Re-running ooniprobe once you have set the environment variable would cause the
+disabled nettest to run. Please, note that we usually have good reasons for disabling
+nettests, including the following reasons:
+
+* making sure that we gradually introduce new nettests to all users by first introducing
+them to a few users and monitoring whether they're working as intended;
+
+* avoid polluting our measurements database with measurements produced by experiments
+that currently produce false positives or other data quality issues.
+`
 
 // OONI_FORCE_ENABLE_EXPERIMENT is the name of the environment variable you should set to "1"
 // to bypass the algorithm preventing disabled by default experiments to be instantiated.