From ab926256a2709c5c112b2f26dad20610a1926654 Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 10:44:38 +0100 Subject: [PATCH 01/10] fix: honor check-in UTC time This diff honors the check-in API time. We create a new package that stores the check-in API time. Because time.Time structs read from JSON do not contain a monotonic clock reading, we store a time.Time containing a monotonic clock reading as well. These two times will always have a bit of offset between them, but such as offset is smaller than the offset between the check-in API time and the probe clock when the probe clock is severely misconfigured. We keep these times in memory. If a probe has not observed a check-in API response or the check-in API contained an empty time, we do not consider the check-in clock to be valid and so the package is basically disabled. Otherwise, we have an API based time reference. We use this reference to: 1. include into measurements the check-in-API based clock reading of when we created a measurement, which allows the OONI backend to determine how safe it is to keep or discard the measurement; 2. warn the user if the offset is +- a few minutes. See https://github.com/ooni/probe/issues/1781 --- internal/checkintime/checkintime.go | 110 ++++++++++++ internal/checkintime/checkintime_test.go | 203 +++++++++++++++++++++++ internal/engine/experiment.go | 39 +++-- internal/model/measurement.go | 8 + internal/probeservices/checkin.go | 8 + 5 files changed, 351 insertions(+), 17 deletions(-) create mode 100644 internal/checkintime/checkintime.go create mode 100644 internal/checkintime/checkintime_test.go diff --git a/internal/checkintime/checkintime.go b/internal/checkintime/checkintime.go new file mode 100644 index 0000000000..95aece67f3 --- /dev/null +++ b/internal/checkintime/checkintime.go @@ -0,0 +1,110 @@ +// 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" +) + +// 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 + + // 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() +} + +// Now returns the current time using as zero time the time saved by +// [Save] rather than the system clock. +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) + out := s.apiTime.Add(delta) + return out, true +} + +// Offset returns the offset between the probe clock and the check-in API clock +// provided that [Save] has been called. If [Save] has not been called, this +// function returns a zero offset and a false value. When the probe clock works +// as intended, there will always be a small positive offset between the probe and +// the API clocks. It's also acceptable to have a small negative offset. +func Offset() (time.Duration, bool) { + return singleton.offset() +} + +func (s *state) offset() (time.Duration, bool) { + s.mu.Lock() + defer s.mu.Unlock() + if !s.good { + return 0, false + } + delta := s.monotonicTimeUTC.Sub(s.apiTime) + return delta, 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) { + delta, good := s.offset() + if !good { + return + } + const smallOffset = 5 * time.Minute + shouldWarn := delta < -smallOffset || delta > smallOffset + if shouldWarn { + logger.Warnf("checkintime: the probe clock is off by %s", delta) + } +} diff --git a/internal/checkintime/checkintime_test.go b/internal/checkintime/checkintime_test.go new file mode 100644 index 0000000000..2caacb9ff5 --- /dev/null +++ b/internal/checkintime/checkintime_test.go @@ -0,0 +1,203 @@ +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 that the offset is also unavailable + t.Run("state.offset", func(t *testing.T) { + delta, good := s.offset() + if good { + t.Fatal("expected false here") + } + if delta != 0 { + t.Fatal("expected zero 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 check-in API specific time + // field has not been initialized, so we get a zero value + 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 that the offset is also unavailable + t.Run("state.offset", func(t *testing.T) { + delta, good := s.offset() + if good { + t.Fatal("expected false here") + } + if delta != 0 { + t.Fatal("expected zero 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 my birthday + apiTime := time.Date(2022, 12, 23, 6, 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 that the offset is available + t.Run("state.offset", func(t *testing.T) { + delta, good := s.offset() + if !good { + t.Fatal("expected true here") + } + const oneMonth = 30 * 24 * 60 * time.Minute + if delta < oneMonth { + t.Fatal("expected more than", oneMonth, "got", delta) + } + }) + + // 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 expect the offset to be small + t.Run("Offset", func(t *testing.T) { + delta, good := Offset() + if !good { + t.Fatal("expected to see true here") + } + if delta < -70*time.Millisecond || delta > 70*time.Millisecond { + t.Fatal("expected around +-70µs, 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..c87f12a496 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,28 @@ 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() + clockoffset, _ := checkintime.Offset() 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 + MeasurementProbeClockOffset: clockoffset, // 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..1160f60225 100644 --- a/internal/model/measurement.go +++ b/internal/model/measurement.go @@ -84,6 +84,14 @@ 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"` + + // MeasurementProbeClockOffset is the OPTIONAL offset between the probe + // clock and the check-in API clock. + MeasurementProbeClockOffset time.Duration `json:"measurement_probe_clock_offset,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 } From 9c5e85d1f27f0eeba9cbd853d212cc7bed41cd84 Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 11:50:50 +0100 Subject: [PATCH 02/10] fix: do not export the offset because it's ~misleading --- internal/checkintime/checkintime.go | 24 ++++++++++++------------ internal/checkintime/checkintime_test.go | 11 ----------- internal/engine/experiment.go | 2 -- internal/model/measurement.go | 4 ---- 4 files changed, 12 insertions(+), 29 deletions(-) diff --git a/internal/checkintime/checkintime.go b/internal/checkintime/checkintime.go index 95aece67f3..44cc46857d 100644 --- a/internal/checkintime/checkintime.go +++ b/internal/checkintime/checkintime.go @@ -56,7 +56,12 @@ func (s *state) save(cur time.Time) { } // Now returns the current time using as zero time the time saved by -// [Save] rather than the system clock. +// [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() } @@ -67,27 +72,22 @@ func (s *state) now() (time.Time, bool) { if !s.good { return time.Time{}, false } - delta := time.Since(s.monotonicTimeUTC) + delta := time.Since(s.monotonicTimeUTC) // RELIABLE diff of monotonic readings out := s.apiTime.Add(delta) return out, true } -// Offset returns the offset between the probe clock and the check-in API clock -// provided that [Save] has been called. If [Save] has not been called, this -// function returns a zero offset and a false value. When the probe clock works -// as intended, there will always be a small positive offset between the probe and -// the API clocks. It's also acceptable to have a small negative offset. -func Offset() (time.Duration, bool) { - return singleton.offset() -} - +// offset returns the offset between the probe clock and the check-in API clock. We do +// not export this method because the return value is only meaningful at the time in which +// we stored the last reading of the API clock. The true offset value would change in +// time if the probe clock jumps forward or backward. func (s *state) offset() (time.Duration, bool) { s.mu.Lock() defer s.mu.Unlock() if !s.good { return 0, false } - delta := s.monotonicTimeUTC.Sub(s.apiTime) + delta := s.monotonicTimeUTC.Sub(s.apiTime) // UNRELIABLE non-monotonic diff return delta, true } diff --git a/internal/checkintime/checkintime_test.go b/internal/checkintime/checkintime_test.go index 2caacb9ff5..8c9486cd95 100644 --- a/internal/checkintime/checkintime_test.go +++ b/internal/checkintime/checkintime_test.go @@ -175,17 +175,6 @@ func TestWorkingAsIntended(t *testing.T) { } }) - // we expect the offset to be small - t.Run("Offset", func(t *testing.T) { - delta, good := Offset() - if !good { - t.Fatal("expected to see true here") - } - if delta < -70*time.Millisecond || delta > 70*time.Millisecond { - t.Fatal("expected around +-70µs, got", delta.Seconds(), "seconds") - } - }) - // we should not warn t.Run("MaybeWarnAboutProbeClockBeingOff", func(t *testing.T) { var called bool diff --git a/internal/engine/experiment.go b/internal/engine/experiment.go index c87f12a496..3fe12d51d9 100644 --- a/internal/engine/experiment.go +++ b/internal/engine/experiment.go @@ -201,13 +201,11 @@ func (e *experiment) SubmitAndUpdateMeasurementContext( func (e *experiment) newMeasurement(input string) *model.Measurement { utctimenow := time.Now().UTC() apiadjustedtimenow, _ := checkintime.Now() - clockoffset, _ := checkintime.Offset() m := &model.Measurement{ DataFormatVersion: model.OOAPIReportDefaultDataFormatVersion, Input: model.MeasurementTarget(input), MeasurementStartTime: utctimenow.Format(dateFormat), MeasurementStartTimeAdjusted: apiadjustedtimenow, // not serialized if zero - MeasurementProbeClockOffset: clockoffset, // not serialized if zero MeasurementStartTimeSaved: utctimenow, ProbeIP: model.DefaultProbeIP, ProbeASN: e.session.ProbeASNString(), diff --git a/internal/model/measurement.go b/internal/model/measurement.go index 1160f60225..e69e8f8d4f 100644 --- a/internal/model/measurement.go +++ b/internal/model/measurement.go @@ -88,10 +88,6 @@ type Measurement struct { // started using as time reference the check-in API time. MeasurementStartTimeAdjusted time.Time `json:"measurement_start_time_adjusted,omitempty"` - // MeasurementProbeClockOffset is the OPTIONAL offset between the probe - // clock and the check-in API clock. - MeasurementProbeClockOffset time.Duration `json:"measurement_probe_clock_offset,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. From 256eaa006b869dc839e2b0802aa3ce0589737be0 Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 11:57:40 +0100 Subject: [PATCH 03/10] x --- internal/checkintime/checkintime_test.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/internal/checkintime/checkintime_test.go b/internal/checkintime/checkintime_test.go index 8c9486cd95..fd6a370be1 100644 --- a/internal/checkintime/checkintime_test.go +++ b/internal/checkintime/checkintime_test.go @@ -54,8 +54,9 @@ func TestWorkingAsIntended(t *testing.T) { }) }) - // This test covers the case where the check-in API specific time - // field has not been initialized, so we get a zero value + // 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 From fbe63ce0fb9bbaa5e0b6d82c5b2792c5abe2713b Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 11:59:53 +0100 Subject: [PATCH 04/10] fix: the offset is a static property --- internal/checkintime/checkintime.go | 26 +++++------------- internal/checkintime/checkintime_test.go | 34 ------------------------ 2 files changed, 6 insertions(+), 54 deletions(-) diff --git a/internal/checkintime/checkintime.go b/internal/checkintime/checkintime.go index 44cc46857d..bc0c70c2e3 100644 --- a/internal/checkintime/checkintime.go +++ b/internal/checkintime/checkintime.go @@ -32,6 +32,9 @@ type state struct { // 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 } @@ -53,6 +56,7 @@ func (s *state) save(cur time.Time) { 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 @@ -77,20 +81,6 @@ func (s *state) now() (time.Time, bool) { return out, true } -// offset returns the offset between the probe clock and the check-in API clock. We do -// not export this method because the return value is only meaningful at the time in which -// we stored the last reading of the API clock. The true offset value would change in -// time if the probe clock jumps forward or backward. -func (s *state) offset() (time.Duration, bool) { - s.mu.Lock() - defer s.mu.Unlock() - if !s.good { - return 0, false - } - delta := s.monotonicTimeUTC.Sub(s.apiTime) // UNRELIABLE non-monotonic diff - return delta, 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) { @@ -98,13 +88,9 @@ func MaybeWarnAboutProbeClockBeingOff(logger model.Logger) { } func (s *state) maybeWarnAboutProbeClockBeingOff(logger model.Logger) { - delta, good := s.offset() - if !good { - return - } const smallOffset = 5 * time.Minute - shouldWarn := delta < -smallOffset || delta > smallOffset + shouldWarn := s.offset < -smallOffset || s.offset > smallOffset if shouldWarn { - logger.Warnf("checkintime: the probe clock is off by %s", delta) + 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 index fd6a370be1..2ed4b965ce 100644 --- a/internal/checkintime/checkintime_test.go +++ b/internal/checkintime/checkintime_test.go @@ -28,17 +28,6 @@ func TestWorkingAsIntended(t *testing.T) { } }) - // we expect that the offset is also unavailable - t.Run("state.offset", func(t *testing.T) { - delta, good := s.offset() - if good { - t.Fatal("expected false here") - } - if delta != 0 { - t.Fatal("expected zero here") - } - }) - // we expect no warning here t.Run("state.maybeWarnAboutTheProbeClockBeingOff", func(t *testing.T) { var called bool @@ -72,17 +61,6 @@ func TestWorkingAsIntended(t *testing.T) { } }) - // we expect that the offset is also unavailable - t.Run("state.offset", func(t *testing.T) { - delta, good := s.offset() - if good { - t.Fatal("expected false here") - } - if delta != 0 { - t.Fatal("expected zero here") - } - }) - // we expect no warning here t.Run("state.maybeWarnAboutProbeClockBeingOff", func(t *testing.T) { var called bool @@ -129,18 +107,6 @@ func TestWorkingAsIntended(t *testing.T) { } }) - // we expect that the offset is available - t.Run("state.offset", func(t *testing.T) { - delta, good := s.offset() - if !good { - t.Fatal("expected true here") - } - const oneMonth = 30 * 24 * 60 * time.Minute - if delta < oneMonth { - t.Fatal("expected more than", oneMonth, "got", delta) - } - }) - // we expect a warning here t.Run("state.maybeWarnAboutProbeClockBeingOff", func(t *testing.T) { var called bool From 92bf7c0fdd8e91b587b973a720057956aa994805 Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 12:01:05 +0100 Subject: [PATCH 05/10] x --- internal/checkintime/checkintime.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/internal/checkintime/checkintime.go b/internal/checkintime/checkintime.go index bc0c70c2e3..0b37f02588 100644 --- a/internal/checkintime/checkintime.go +++ b/internal/checkintime/checkintime.go @@ -88,6 +88,9 @@ func MaybeWarnAboutProbeClockBeingOff(logger model.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 { From fc435880e031238495483583e5d82f32964a4cbd Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 12:12:27 +0100 Subject: [PATCH 06/10] x --- internal/checkintime/checkintime.go | 33 +++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/internal/checkintime/checkintime.go b/internal/checkintime/checkintime.go index 0b37f02588..664978f2a7 100644 --- a/internal/checkintime/checkintime.go +++ b/internal/checkintime/checkintime.go @@ -16,6 +16,39 @@ import ( "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 and we cannot serialize the proper monotonic reading. + + 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 jumps, which + includes adjusting the system clock using NTP et al. + + 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 { From 23fe54ac0d395a588ef78c64d4d11f842e47ba14 Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 12:24:51 +0100 Subject: [PATCH 07/10] fix: it's never wrong to try and be a bit more precise --- internal/checkintime/checkintime.go | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/internal/checkintime/checkintime.go b/internal/checkintime/checkintime.go index 664978f2a7..6b0f822214 100644 --- a/internal/checkintime/checkintime.go +++ b/internal/checkintime/checkintime.go @@ -22,12 +22,21 @@ import ( 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 and we cannot serialize the proper monotonic reading. + clock" time and we cannot serialize the underlying, and system + dependent, monotonic clock reading. Additionally, on Windows, the + monotonic clock uses the interrupt time, which countes the time since + boot in 100ns intervals, so serializing it is dangerous. + + 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 jumps, which - includes adjusting the system clock using NTP et al. + 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.) Therefore, the implementation of this package works entirely on memory and requires calling the check-in API before performing any other From 386538c660a054a516bb8429fc25ca339d41fbbd Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 12:28:04 +0100 Subject: [PATCH 08/10] more precise design doc --- internal/checkintime/checkintime.go | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/internal/checkintime/checkintime.go b/internal/checkintime/checkintime.go index 6b0f822214..12fd581541 100644 --- a/internal/checkintime/checkintime.go +++ b/internal/checkintime/checkintime.go @@ -22,10 +22,10 @@ import ( 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 and we cannot serialize the underlying, and system - dependent, monotonic clock reading. Additionally, on Windows, the - monotonic clock uses the interrupt time, which countes the time since - boot in 100ns intervals, so serializing it is dangerous. + 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 @@ -36,7 +36,8 @@ import ( 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.) + 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 From 5e8df1eaf926c6f0f82eeddb4f9813aed0f25930 Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 12:32:10 +0100 Subject: [PATCH 09/10] lol --- internal/checkintime/checkintime_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/checkintime/checkintime_test.go b/internal/checkintime/checkintime_test.go index 2ed4b965ce..0d00713772 100644 --- a/internal/checkintime/checkintime_test.go +++ b/internal/checkintime/checkintime_test.go @@ -83,7 +83,7 @@ func TestWorkingAsIntended(t *testing.T) { s := &state{} // pretend the API time is my birthday - apiTime := time.Date(2022, 12, 23, 6, 36, 0, 0, time.UTC) + apiTime := time.Date(2022, 12, 23, 7, 36, 0, 0, time.UTC) s.save(apiTime) // await a little bit From 9913c808d7d0d5045a8d24b288e35fd1c65e5900 Mon Sep 17 00:00:00 2001 From: Simone Basso Date: Tue, 21 Mar 2023 12:32:55 +0100 Subject: [PATCH 10/10] avoid references to real human beings --- internal/checkintime/checkintime_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/checkintime/checkintime_test.go b/internal/checkintime/checkintime_test.go index 0d00713772..14c9dd1e67 100644 --- a/internal/checkintime/checkintime_test.go +++ b/internal/checkintime/checkintime_test.go @@ -82,7 +82,7 @@ func TestWorkingAsIntended(t *testing.T) { // create empty state s := &state{} - // pretend the API time is my birthday + // 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)