feat: honor check-in UTC time

internal/checkintime/checkintime.go

@@ -0,0 +1,142 @@
+// Package checkintime tracks the check-in API time. By tracking such
+// a time we can perform the following actions:
+//
+// 1. submit measurements with a reference time based on the check-in API
+// time rather than on the probe clock;
+//
+// 2. warn the user that the probe clock is definitely off.
+//
+// See https://github.com/ooni/probe/issues/1781 for more details.
+package checkintime
+
+import (
+	"sync"
+	"time"
+
+	"github.com/ooni/probe-cli/v3/internal/model"
+)
+
+/*
+	Design note
+	-----------
+
+	We cannot store on disk the monotonic clock readings because we are
+	only allowed to serialize time.Time as a string representing a "wall
+	clock" time. Also, the monotonic clock is system dependent and may
+	not refer to a well defined zero time. For example, on Windows, the
+	monotonic clock uses the "interrupt time", which countes the time since
+	boot in 100ns intervals, so serializing it is not a good idea.
+
+	See https://cs.opensource.google/go/go/+/refs/tags/go1.20.2:src/runtime/time_windows_amd64.s
+	See https://learn.microsoft.com/en-us/windows/win32/sysinfo/interrupt-time
+	See https://learn.microsoft.com/en-us/windows/win32/sysinfo/system-time
+
+	Storing wall clocks on disk could be done in UTC to account for the
+	user jumping across timezones. Still, even if we did that, the stored
+	reading would still be wrong when there are wall clock adjusments, which
+	includes adjusting the system clock using NTP et al. (There are cases
+	in which the clock adjustment is a jump and cases in which it is relatively
+	monotonic; see https://man.openbsd.org/settimeofday#CAVEATS as well as
+	https://learn.microsoft.com/en-us/windows/win32/sysinfo/system-time.)
+
+	Therefore, the implementation of this package works entirely on memory
+	and requires calling the check-in API before performing any other
+	operation that requires timing.
+
+	This design choice is ~fine since we're moving towards a direction
+	where the check-in API will be called before running tests. Yet,
+	it also means that we wouldn't be able to verify the probe clock when
+	using a cached check-in response in the future.
+
+	A possible future improvement would be for this package to export a
+	"best effort" clock using either the system clock or the API clock
+	to provide time.Time values to TLS and QUIC. The choice on which
+	clock to use would depend on the measured clocks offset. This would
+	theoretically allow us to make TLS handshakes work even when the
+	probe clock is singificantly off. However, it's also true that we
+	would like to make TLS handshake verification non-fatal, because it
+	helps us to collect more data. Because of this reason, I have not
+	implemented subverting the TLS verification reference clock.
+*/
+
+// state contains the [checkintime] state. The zero value
+// of this structure is ready to use.
+type state struct {
+	// apiTime contains the time according to the check-in API.
+	apiTime time.Time
+
+	// good indicates whether we have good data.
+	good bool
+
+	// monotonicTimeUTC contains the monotonic UTC clock reading when we
+	// saved the apiTime. We need this variable because times unmarshalled
+	// from JSON contain no monotonic clock readings.
+	//
+	// See https://github.com/golang/go/blob/72c58fb/src/time/time.go#L58.
+	monotonicTimeUTC time.Time
+
+	// offset is the offset between monotonicTimeUTC and apiTime.
+	offset time.Duration
+
+	// mu provides mutual exclusion.
+	mu sync.Mutex
+}
+
+// singleton is the [checkintime] singleton.
+var singleton = &state{}
+
+// Save saves the time according to the check-in API.
+func Save(cur time.Time) {
+	singleton.save(cur)
+}
+
+func (s *state) save(cur time.Time) {
+	if cur.IsZero() {
+		return
+	}
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	s.apiTime = cur
+	s.good = true
+	s.monotonicTimeUTC = time.Now().UTC()
+	s.offset = s.monotonicTimeUTC.Sub(s.apiTime) // UNRELIABLE non-monotonic diff
+}
+
+// Now returns the current time using as zero time the time saved by
+// [Save] rather than the system clock. The time returned by this call
+// is reliable because it consists of the diff between two monotonic
+// clock readings of the system's monotonic clock added to the zero time
+// reference provided by the check-in API. When the probe clock is OK,
+// this value will always be slightly in the past, because we cannot
+// account for the time elapsed transferring the check-in response.
+func Now() (time.Time, bool) {
+	return singleton.now()
+}
+
+func (s *state) now() (time.Time, bool) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	if !s.good {
+		return time.Time{}, false
+	}
+	delta := time.Since(s.monotonicTimeUTC) // RELIABLE diff of monotonic readings
+	out := s.apiTime.Add(delta)
+	return out, true
+}
+
+// MaybeWarnAboutProbeClockBeingOff emits a warning if the probe clock is off
+// compared to the clock used by the check-in API.
+func MaybeWarnAboutProbeClockBeingOff(logger model.Logger) {
+	singleton.maybeWarnAboutProbeClockBeingOff(logger)
+}
+
+func (s *state) maybeWarnAboutProbeClockBeingOff(logger model.Logger) {
+	if !s.good {
+		return
+	}
+	const smallOffset = 5 * time.Minute
+	shouldWarn := s.offset < -smallOffset || s.offset > smallOffset
+	if shouldWarn {
+		logger.Warnf("checkintime: the probe clock is off by %s", s.offset)
+	}
+}

internal/checkintime/checkintime_test.go

@@ -0,0 +1,159 @@
+package checkintime
+
+import (
+	"testing"
+	"time"
+
+	"github.com/ooni/probe-cli/v3/internal/model/mocks"
+)
+
+// Make sure that we can compute times relative to the base time specified
+// by the check-in API as opposed to the system clock. It does not matter
+// which clock is wrong in this test, by the way. In reality, the wrong clock
+// is the probe clock, while in this test the API clock is wrong.
+func TestWorkingAsIntended(t *testing.T) {
+
+	// This test covers the case where we've not initialized the state yet
+	t.Run("when we have not set the apiTime yet", func(t *testing.T) {
+		s := &state{}
+
+		// we expect the current time to be unavailable
+		t.Run("state.now", func(t *testing.T) {
+			out, good := s.now()
+			if good {
+				t.Fatal("expected false here")
+			}
+			if !out.IsZero() {
+				t.Fatal("expected zero value here")
+			}
+		})
+
+		// we expect no warning here
+		t.Run("state.maybeWarnAboutTheProbeClockBeingOff", func(t *testing.T) {
+			var called bool
+			logger := &mocks.Logger{
+				MockWarnf: func(format string, v ...interface{}) {
+					called = true
+				},
+			}
+			s.maybeWarnAboutProbeClockBeingOff(logger)
+			if called {
+				t.Fatal("expected false here")
+			}
+		})
+	})
+
+	// This test covers the case where the input time is zero. It should not
+	// happen in practice, because the parsing of the check-in API response
+	// fails if the response does not contain a correctly formatted time string.
+	t.Run("when the apiTime is zero", func(t *testing.T) {
+		s := &state{}
+		s.save(time.Time{}) // zero
+
+		// we expect the current time to be unavailable
+		t.Run("state.now", func(t *testing.T) {
+			out, good := s.now()
+			if good {
+				t.Fatal("expected false here")
+			}
+			if !out.IsZero() {
+				t.Fatal("expected zero value here")
+			}
+		})
+
+		// we expect no warning here
+		t.Run("state.maybeWarnAboutProbeClockBeingOff", func(t *testing.T) {
+			var called bool
+			logger := &mocks.Logger{
+				MockWarnf: func(format string, v ...interface{}) {
+					called = true
+				},
+			}
+			s.maybeWarnAboutProbeClockBeingOff(logger)
+			if called {
+				t.Fatal("expected false here")
+			}
+		})
+	})
+
+	// This test covers the case where we've been given a valid value from
+	// the check-in API, so we can compute offsets etc.
+	t.Run("after we have set the apiTime", func(t *testing.T) {
+		// create empty state
+		s := &state{}
+
+		// pretend the API time is some time in the past
+		apiTime := time.Date(2022, 12, 23, 7, 36, 0, 0, time.UTC)
+		s.save(apiTime)
+
+		// await a little bit
+		time.Sleep(time.Second)
+
+		// obtain the current time according to [state]
+		t.Run("state.now", func(t *testing.T) {
+			now, good := s.now()
+
+			// the current time must be good
+			if !good {
+				t.Fatal("expected to see true here")
+			}
+
+			// compute delta between now and the apiTime
+			delta := now.Sub(apiTime)
+
+			// make sure the elapsed time is around one second
+			if delta < 700*time.Millisecond || delta > 1300*time.Millisecond {
+				t.Fatal("expected around one second, got", delta.Seconds(), "seconds")
+			}
+		})
+
+		// we expect a warning here
+		t.Run("state.maybeWarnAboutProbeClockBeingOff", func(t *testing.T) {
+			var called bool
+			logger := &mocks.Logger{
+				MockWarnf: func(format string, v ...interface{}) {
+					called = true
+				},
+			}
+			s.maybeWarnAboutProbeClockBeingOff(logger)
+			if !called {
+				t.Fatal("expected true here")
+			}
+		})
+	})
+
+	t.Run("additional tests to cover the public API", func(t *testing.T) {
+		// save the current time as the API time
+		apiTime := time.Now()
+		Save(apiTime)
+
+		// await a little bit
+		time.Sleep(time.Second)
+
+		// we expect to be able to get the current time
+		t.Run("Now", func(t *testing.T) {
+			now, good := Now()
+			if !good {
+				t.Fatal("expected to see true here")
+			}
+			delta := now.Sub(apiTime)
+			if delta < 700*time.Millisecond || delta > 1300*time.Millisecond {
+				t.Fatal("expected around one second, got", delta.Seconds(), "seconds")
+			}
+		})
+
+		// we should not warn
+		t.Run("MaybeWarnAboutProbeClockBeingOff", func(t *testing.T) {
+			var called bool
+			logger := &mocks.Logger{
+				MockWarnf: func(format string, v ...interface{}) {
+					called = true
+				},
+			}
+			MaybeWarnAboutProbeClockBeingOff(logger)
+			if called {
+				t.Fatal("expected false here")
+			}
+		})
+	})
+}

internal/engine/experiment.go

@@ -14,6 +14,7 @@ import (
 	"time"
 
 	"github.com/ooni/probe-cli/v3/internal/bytecounter"
+	"github.com/ooni/probe-cli/v3/internal/checkintime"
 	"github.com/ooni/probe-cli/v3/internal/model"
 	"github.com/ooni/probe-cli/v3/internal/probeservices"
 	"github.com/ooni/probe-cli/v3/internal/runtimex"
@@ -199,24 +200,26 @@ func (e *experiment) SubmitAndUpdateMeasurementContext(
 // newMeasurement creates a new measurement for this experiment with the given input.
 func (e *experiment) newMeasurement(input string) *model.Measurement {
 	utctimenow := time.Now().UTC()
+	apiadjustedtimenow, _ := checkintime.Now()
 	m := &model.Measurement{
-		DataFormatVersion:         model.OOAPIReportDefaultDataFormatVersion,
-		Input:                     model.MeasurementTarget(input),
-		MeasurementStartTime:      utctimenow.Format(dateFormat),
-		MeasurementStartTimeSaved: utctimenow,
-		ProbeIP:                   model.DefaultProbeIP,
-		ProbeASN:                  e.session.ProbeASNString(),
-		ProbeCC:                   e.session.ProbeCC(),
-		ProbeNetworkName:          e.session.ProbeNetworkName(),
-		ReportID:                  e.ReportID(),
-		ResolverASN:               e.session.ResolverASNString(),
-		ResolverIP:                e.session.ResolverIP(),
-		ResolverNetworkName:       e.session.ResolverNetworkName(),
-		SoftwareName:              e.session.SoftwareName(),
-		SoftwareVersion:           e.session.SoftwareVersion(),
-		TestName:                  e.testName,
-		TestStartTime:             e.testStartTime,
-		TestVersion:               e.testVersion,
+		DataFormatVersion:            model.OOAPIReportDefaultDataFormatVersion,
+		Input:                        model.MeasurementTarget(input),
+		MeasurementStartTime:         utctimenow.Format(dateFormat),
+		MeasurementStartTimeAdjusted: apiadjustedtimenow, // not serialized if zero
+		MeasurementStartTimeSaved:    utctimenow,
+		ProbeIP:                      model.DefaultProbeIP,
+		ProbeASN:                     e.session.ProbeASNString(),
+		ProbeCC:                      e.session.ProbeCC(),
+		ProbeNetworkName:             e.session.ProbeNetworkName(),
+		ReportID:                     e.ReportID(),
+		ResolverASN:                  e.session.ResolverASNString(),
+		ResolverIP:                   e.session.ResolverIP(),
+		ResolverNetworkName:          e.session.ResolverNetworkName(),
+		SoftwareName:                 e.session.SoftwareName(),
+		SoftwareVersion:              e.session.SoftwareVersion(),
+		TestName:                     e.testName,
+		TestStartTime:                e.testStartTime,
+		TestVersion:                  e.testVersion,
 	}
 	m.AddAnnotation("architecture", runtime.GOARCH)
 	m.AddAnnotation("engine_name", "ooniprobe-engine")

internal/model/measurement.go

@@ -84,6 +84,10 @@ type Measurement struct {
 	// MeasurementStartTime is the time when the measurement started
 	MeasurementStartTime string `json:"measurement_start_time"`
 
+	// MeasurementStartTimeAdjusted is the OPTIONAL time when the measurement
+	// started using as time reference the check-in API time.
+	MeasurementStartTimeAdjusted time.Time `json:"measurement_start_time_adjusted,omitempty"`
+
 	// MeasurementStartTimeSaved is the moment in time when we
 	// started the measurement. This is not included into the JSON
 	// and is only used within the ./internal pkg as a "zero" time.

internal/probeservices/checkin.go

@@ -4,6 +4,7 @@ import (
 	"context"
 
 	"github.com/ooni/probe-cli/v3/internal/checkincache"
+	"github.com/ooni/probe-cli/v3/internal/checkintime"
 	"github.com/ooni/probe-cli/v3/internal/httpapi"
 	"github.com/ooni/probe-cli/v3/internal/model"
 	"github.com/ooni/probe-cli/v3/internal/ooapi"
@@ -29,5 +30,12 @@ func (c Client) CheckIn(
 
 	// make sure we track selected parts of the response
 	_ = checkincache.Store(c.KVStore, resp)
+
+	// make sure we save the current time according to the check-in API
+	checkintime.Save(resp.UTCTime)
+
+	// emit warning if the probe clock is off
+	checkintime.MaybeWarnAboutProbeClockBeingOff(c.Logger)
+
 	return resp, nil
 }