diff --git a/internal/checkintime/checkintime.go b/internal/checkintime/checkintime.go new file mode 100644 index 0000000000..12fd581541 --- /dev/null +++ b/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) + } +} diff --git a/internal/checkintime/checkintime_test.go b/internal/checkintime/checkintime_test.go new file mode 100644 index 0000000000..14c9dd1e67 --- /dev/null +++ b/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") + } + }) + }) +} diff --git a/internal/engine/experiment.go b/internal/engine/experiment.go index 5a850693ae..3fe12d51d9 100644 --- a/internal/engine/experiment.go +++ b/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") diff --git a/internal/model/measurement.go b/internal/model/measurement.go index 7cd2a8e13e..e69e8f8d4f 100644 --- a/internal/model/measurement.go +++ b/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. diff --git a/internal/probeservices/checkin.go b/internal/probeservices/checkin.go index 08b12583e7..339de9d2d7 100644 --- a/internal/probeservices/checkin.go +++ b/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 }