Instrument timezone offset workaround

This requires more changes than I'd like,
but recording metrics internally requires a valid `Glean` to be passed around.
Because we use `local_now_with_offset` right when we construct a `Glean` instance,
we need to first finish that and _then_ report it.
In other places we have a `Glean` around and can pass it on.
So we split up the code and do the recording externally when used during
initialization, and internally whenever we can pass in a valid `Glean`.

docs/user/user/collected-metrics/metrics.md

@@ -143,6 +143,7 @@ In addition to those built-in metrics, the following metrics are added to the pi
 | glean.database.size |[memory_distribution](https://mozilla.github.io/glean/book/user/metrics/memory_distribution.html) |The size of the database file at startup.  |[Bug 1656589](https://bugzilla.mozilla.org/show_bug.cgi?id=1656589#c7)||never |1 |
 | glean.error.io |[counter](https://mozilla.github.io/glean/book/user/metrics/counter.html) |The number of times we encountered an IO error when writing a pending ping to disk.  |[Bug 1686233](https://bugzilla.mozilla.org/show_bug.cgi?id=1686233#c2)||never |1 |
 | glean.error.preinit_tasks_overflow |[counter](https://mozilla.github.io/glean/book/user/metrics/counter.html) |The number of tasks queued in the pre-initialization buffer. Only sent if the buffer overflows.  |[Bug 1609482](https://bugzilla.mozilla.org/show_bug.cgi?id=1609482#c3)||never |1 |
+| glean.time.invalid_timezone_offset |[counter](https://mozilla.github.io/glean/book/user/metrics/counter.html) |Counts the number of times we encountered an invalid timezone offset when trying to get the current time. A timezone offset is invalid if it is outside [-24h, +24h]. If invalid a UTC offset is used (+0h).  |[Bug 1611770](https://bugzilla.mozilla.org/show_bug.cgi?id=1611770#c9)||2021-06-30 |1 |
 | glean.upload.deleted_pings_after_quota_hit |[counter](https://mozilla.github.io/glean/book/user/metrics/counter.html) |The number of pings deleted after the quota for the size of the pending pings directory or number of files is hit. Since quota is only calculated for the pending pings directory, and deletion request ping live in a different directory, deletion request pings are never deleted.  |[Bug 1601550](https://bugzilla.mozilla.org/show_bug.cgi?id=1601550#c3)||never |1 |
 | glean.upload.discarded_exceeding_pings_size |[memory_distribution](https://mozilla.github.io/glean/book/user/metrics/memory_distribution.html) |The size of pings that exceeded the maximum ping size allowed for upload.  |[Bug 1597761](https://bugzilla.mozilla.org/show_bug.cgi?id=1597761#c10)||never |1 |
 | glean.upload.pending_pings |[counter](https://mozilla.github.io/glean/book/user/metrics/counter.html) |The total number of pending pings at startup. This does not include deletion-request pings.  |[Bug 1665041](https://bugzilla.mozilla.org/show_bug.cgi?id=1665041#c23)||never |1 |

glean-core/metrics.yaml

@@ -620,3 +620,25 @@ glean.validation:
       - glean-team@mozilla.com
     expires:
       never
+
+glean.time:
+  invalid_timezone_offset:
+    type: counter
+    description: |
+      Counts the number of times we encountered an invalid timezone offset
+      when trying to get the current time.
+      A timezone offset is invalid if it is outside [-24h, +24h].
+      If invalid a UTC offset is used (+0h).
+    lifetime: ping
+    send_in_pings:
+      - metrics
+    bugs:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1611770
+    data_reviews:
+      - https://bugzilla.mozilla.org/show_bug.cgi?id=1611770#c9
+    data_sensitivity:
+      - technical
+    notification_emails:
+      - jrediger@mozilla.com
+      - glean-team@mozilla.com
+    expires: 2021-06-30

glean-core/src/internal_metrics.rs

@@ -10,14 +10,24 @@ pub struct CoreMetrics {
     pub first_run_date: DatetimeMetric,
     pub first_run_hour: DatetimeMetric,
     pub os: StringMetric,
+}
 
+#[derive(Debug)]
+pub struct AdditionalMetrics {
     /// The number of times we encountered an IO error
     /// when writing a pending ping to disk.
-    ///
-    /// **Note**: Not a _core_ metric, but an error metric,
-    /// placed here for the lack of a more suitable part in the Glean struct.
     pub io_errors: CounterMetric,
+
+    /// A count of the pings submitted, by ping type.
     pub pings_submitted: LabeledMetric<CounterMetric>,
+
+    /// The number of times we encountered an invalid timezone offset
+    /// (outside of [-24, +24] hours).
+    ///
+    /// **Note**: This metric has an expiration date set.
+    /// However because it's statically defined here we can't specify that.
+    /// Needs to be removed after 2021-06-30.
+    pub invalid_timezone_offset: CounterMetric,
 }
 
 impl CoreMetrics {
@@ -64,7 +74,13 @@ impl CoreMetrics {
                 disabled: false,
                 dynamic_label: None,
             }),
+        }
+    }
+}
 
+impl AdditionalMetrics {
+    pub fn new() -> AdditionalMetrics {
+        AdditionalMetrics {
             io_errors: CounterMetric::new(CommonMetricData {
                 name: "io".into(),
                 category: "glean.error".into(),
@@ -85,6 +101,15 @@ impl CoreMetrics {
                 }),
                 None,
             ),
+
+            invalid_timezone_offset: CounterMetric::new(CommonMetricData {
+                name: "invalid_timezone_offset".into(),
+                category: "glean.time".into(),
+                send_in_pings: vec!["metrics".into()],
+                lifetime: Lifetime::Ping,
+                disabled: false,
+                dynamic_label: None,
+            }),
         }
     }
 }

glean-core/src/lib.rs

@@ -51,7 +51,7 @@ pub use crate::error::{Error, ErrorKind, Result};
 pub use crate::error_recording::{test_get_num_recorded_errors, ErrorType};
 use crate::event_database::EventDatabase;
 pub use crate::histogram::HistogramType;
-use crate::internal_metrics::{CoreMetrics, DatabaseMetrics};
+use crate::internal_metrics::{AdditionalMetrics, CoreMetrics, DatabaseMetrics};
 use crate::internal_pings::InternalPings;
 use crate::metrics::{Metric, MetricType, PingType};
 use crate::ping::PingMaker;
@@ -174,6 +174,7 @@ pub struct Glean {
     data_store: Option<Database>,
     event_data_store: EventDatabase,
     core_metrics: CoreMetrics,
+    additional_metrics: AdditionalMetrics,
     database_metrics: DatabaseMetrics,
     internal_pings: InternalPings,
     data_path: PathBuf,
@@ -213,24 +214,35 @@ impl Glean {
             let _scanning_thread = upload_manager.scan_pending_pings_directories();
         }
 
-        Ok(Self {
+        let (start_time, start_time_is_corrected) = local_now_with_offset();
+        let this = Self {
             upload_enabled: cfg.upload_enabled,
             // In the subprocess, we want to avoid accessing the database entirely.
             // The easiest way to ensure that is to just not initialize it.
             data_store: None,
             event_data_store,
             core_metrics: CoreMetrics::new(),
+            additional_metrics: AdditionalMetrics::new(),
             database_metrics: DatabaseMetrics::new(),
             internal_pings: InternalPings::new(),
             upload_manager,
             data_path: PathBuf::from(&cfg.data_path),
             application_id,
             ping_registry: HashMap::new(),
-            start_time: local_now_with_offset(),
+            start_time,
             max_events: cfg.max_events.unwrap_or(DEFAULT_MAX_EVENTS),
             is_first_run: false,
             debug: DebugOptions::new(),
-        })
+        };
+
+        // Can't use `local_now_with_offset_and_record` above, because we needed a valid `Glean` first.
+        if start_time_is_corrected {
+            this.additional_metrics
+                .invalid_timezone_offset
+                .add(&this, 1);
+        }
+
+        Ok(this)
     }
 
     /// Creates and initializes a new Glean object.
@@ -631,14 +643,14 @@ impl Glean {
                 // that is the only way to know *if* it will be submitted). The
                 // implication of this is that the count for a metrics ping will
                 // be included in the *next* metrics ping.
-                self.core_metrics
+                self.additional_metrics
                     .pings_submitted
                     .get(&ping.name)
                     .add(&self, 1);
 
                 if let Err(e) = ping_maker.store_ping(&self.get_data_path(), &ping) {
                     log::warn!("IO error while writing ping to file: {}. Enqueuing upload of what we have in memory.", e);
-                    self.core_metrics.io_errors.add(self, 1);
+                    self.additional_metrics.io_errors.add(self, 1);
                     let content = ::serde_json::to_string(&ping.content)?;
                     self.upload_manager.enqueue_ping(
                         self,

glean-core/src/lib_unit_tests.rs

@@ -401,7 +401,7 @@ fn correct_order() {
         Counter(0),
         CustomDistributionExponential(Histogram::exponential(1, 500, 10)),
         CustomDistributionLinear(Histogram::linear(1, 500, 10)),
-        Datetime(local_now_with_offset(), TimeUnit::Second),
+        Datetime(local_now_with_offset().0, TimeUnit::Second),
         Experiment(RecordedExperimentData { branch: "branch".into(), extra: None, }),
         Quantity(0),
         String("glean".into()),
@@ -897,7 +897,7 @@ fn records_io_errors() {
     assert!(submitted.is_ok());
     assert!(submitted.unwrap());
 
-    let metric = &glean.core_metrics.io_errors;
+    let metric = &glean.additional_metrics.io_errors;
     assert_eq!(
         1,
         metric.test_get_value(&glean, "metrics").unwrap(),
@@ -931,3 +931,20 @@ fn test_activity_api() {
     // Check that we set everything we needed for the 'inactuve' status.
     assert!(!glean.is_dirty_flag_set());
 }
+
+/// We explicitly test that NO invalid timezone offset was recorded.
+/// If it _does_ happen and fails on a developer machine or CI, we better know about it.
+#[test]
+fn handles_local_now_gracefully() {
+    let _ = env_logger::builder().is_test(true).try_init();
+
+    let dir = tempfile::tempdir().unwrap();
+    let (glean, _) = new_glean(Some(dir));
+
+    let metric = &glean.additional_metrics.invalid_timezone_offset;
+    assert_eq!(
+        None,
+        metric.test_get_value(&glean, "metrics"),
+        "Timezones should be valid"
+    );
+}

glean-core/src/metrics/datetime.rs

@@ -9,7 +9,7 @@ use crate::metrics::time_unit::TimeUnit;
 use crate::metrics::Metric;
 use crate::metrics::MetricType;
 use crate::storage::StorageManager;
-use crate::util::{get_iso_time_string, local_now_with_offset};
+use crate::util::{get_iso_time_string, local_now_with_offset_and_record};
 use crate::CommonMetricData;
 use crate::Glean;
 
@@ -117,7 +117,7 @@ impl DatetimeMetric {
             return;
         }
 
-        let value = value.unwrap_or_else(local_now_with_offset);
+        let value = value.unwrap_or_else(|| local_now_with_offset_and_record(&glean));
         let value = Metric::Datetime(value, self.time_unit);
         glean.storage().record(glean, &self.meta, &value)
     }

glean-core/src/ping/mod.rs

@@ -15,7 +15,7 @@ use crate::common_metric_data::{CommonMetricData, Lifetime};
 use crate::metrics::{CounterMetric, DatetimeMetric, Metric, MetricType, PingType, TimeUnit};
 use crate::storage::StorageManager;
 use crate::upload::HeaderMap;
-use crate::util::{get_iso_time_string, local_now_with_offset};
+use crate::util::{get_iso_time_string, local_now_with_offset_and_record};
 use crate::{
     Glean, Result, DELETION_REQUEST_PINGS_DIRECTORY, INTERNAL_STORAGE, PENDING_PINGS_DIRECTORY,
 };
@@ -112,7 +112,7 @@ impl PingMaker {
         let start_time_data = start_time
             .get_value(glean, INTERNAL_STORAGE)
             .unwrap_or_else(|| glean.start_time());
-        let end_time_data = local_now_with_offset();
+        let end_time_data = local_now_with_offset_and_record(&glean);
 
         // Update the start time with the current time.
         start_time.set(glean, Some(end_time_data));

glean-core/src/util.rs

@@ -47,7 +47,9 @@ pub fn get_iso_time_string(datetime: DateTime<FixedOffset>, truncate_to: TimeUni
 /// Get the current date & time with a fixed-offset timezone.
 ///
 /// This converts from the `Local` timezone into its fixed-offset equivalent.
-pub(crate) fn local_now_with_offset() -> DateTime<FixedOffset> {
+/// If a timezone outside of [-24h, +24h] is detected it corrects the timezone offset to UTC (+0).
+/// The return value will signal if the timezone offset was corrected.
+pub(crate) fn local_now_with_offset() -> (DateTime<FixedOffset>, bool) {
     #[cfg(target_os = "windows")]
     {
         // `Local::now` takes the user's timezone offset
@@ -76,14 +78,35 @@ pub(crate) fn local_now_with_offset() -> DateTime<FixedOffset> {
         // https://docs.rs/chrono/0.4.10/src/chrono/offset/local.rs.html#37
         let offset = tm.tm_utcoff;
         if let None = FixedOffset::east_opt(offset) {
+            log::warn!(
+                "Detected invalid timezone offset: {}. Using UTC fallback.",
+                offset
+            );
             let now: DateTime<Utc> = Utc::now();
             let utc_offset = FixedOffset::east(0);
-            return now.with_timezone(&utc_offset);
+            return (now.with_timezone(&utc_offset), true);
         }
     }
 
     let now: DateTime<Local> = Local::now();
-    now.with_timezone(now.offset())
+    (now.with_timezone(now.offset()), false)
+}
+
+/// Get the current date & time with a fixed-offset timezone.
+///
+/// This converts from the `Local` timezone into its fixed-offset equivalent.
+/// If a timezone outside of [-24h, +24h] is detected it corrects the timezone offset to UTC (+0).
+/// The corresponding error counter is incremented in this case.
+pub(crate) fn local_now_with_offset_and_record(glean: &Glean) -> DateTime<FixedOffset> {
+    let (now, is_corrected) = local_now_with_offset();
+    if is_corrected {
+        glean
+            .additional_metrics
+            .invalid_timezone_offset
+            .add(&glean, 1);
+    }
+
+    now
 }
 
 /// Truncates a string, ensuring that it doesn't end in the middle of a codepoint.
@@ -274,7 +297,11 @@ mod test {
     #[test]
     fn local_now_gets_the_time() {
         let now = Local::now();
-        let fixed_now = local_now_with_offset();
+        let (fixed_now, is_corrected) = local_now_with_offset();
+
+        // We explicitly test that NO invalid timezone offset was recorded.
+        // If it _does_ happen and fails on a developer machine or CI, we better know about it.
+        assert!(!is_corrected, "Timezone offset should be valid.");
 
         // We can't compare across differing timezones, so we just compare the UTC timestamps.
         // The second timestamp should be just a few nanoseconds later.