Skip to content

Commit ef9bac4

Browse files
committed
Clamp event timestamps to i64::MAX
BigQuery's integer type is a signed 64-bit value, while we collect unsigned ones. Timestamps are in milliseconds, so 9223372036854775807 (i64::MAX) ms is about 4.5 billion years, or roughly 1/15 of the age of earth. I think we should be fine with that for a little while longer. So any such value _should_ not happen. But it does in 0.002% of pings and thus data ends up in `additional_properties` instead of where it belongs. By clamping we might reduce that %age further. An event with that timestamp is most likely still not useful, but maybe the others are? One more problem is: Should we report this as an issue? If so how? Right now we don't have the APIs to tie that back to a specific event other then the one we own. But then our error types don't express the right things.
1 parent 770859d commit ef9bac4

File tree

3 files changed

+95
-0
lines changed

3 files changed

+95
-0
lines changed

glean-core/metrics.yaml

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -647,6 +647,25 @@ glean.error:
647647
- jrediger@mozilla.com
648648
expires: never
649649

650+
event_timestamp_clamped:
651+
type: counter
652+
description: |
653+
The number of times we had to clamp an event timestamp
654+
for exceeding the range of a signed 64-bit integer (9223372036854775807).
655+
send_in_pings:
656+
- events
657+
- health
658+
bugs:
659+
- https://bugzilla.mozilla.org/show_bug.cgi?id=1873482
660+
data_reviews:
661+
- https://bugzilla.mozilla.org/show_bug.cgi?id=1873482
662+
data_sensitivity:
663+
- technical
664+
notification_emails:
665+
- glean-team@mozilla.com
666+
- jrediger@mozilla.com
667+
expires: 2026-05-31
668+
650669
glean.upload:
651670
ping_upload_failure:
652671
type: labeled_counter

glean-core/src/event_database/mod.rs

Lines changed: 63 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -560,6 +560,22 @@ impl EventDatabase {
560560
// Let's fix cur_ec up and hope this isn't a sign something big is broken.
561561
cur_ec = execution_counter;
562562
}
563+
564+
// event timestamp is a `u64`, but BigQuery uses `i64` (signed!) everywhere. Let's clamp the value to make
565+
// sure we stay within bounds.
566+
if event.event.timestamp > i64::MAX as u64 {
567+
glean
568+
.additional_metrics
569+
.event_timestamp_clamped
570+
.add_sync(glean, 1);
571+
log::warn!(
572+
"Calculated event timestamp was too high. Got: {}, max: {}",
573+
event.event.timestamp,
574+
i64::MAX,
575+
);
576+
event.event.timestamp = event.event.timestamp.clamp(0, i64::MAX as u64);
577+
}
578+
563579
if highest_ts > event.event.timestamp {
564580
// Even though we sorted everything, something in the
565581
// execution_counter or glean.startup.date math went awry.
@@ -1357,4 +1373,51 @@ mod test {
13571373
)
13581374
.is_err());
13591375
}
1376+
1377+
#[test]
1378+
fn normalize_store_clamps_timestamp() {
1379+
// TODO
1380+
let (glean, _dir) = new_glean(None);
1381+
1382+
let store_name = "store-name";
1383+
let event = RecordedEvent {
1384+
category: "category".into(),
1385+
name: "name".into(),
1386+
..Default::default()
1387+
};
1388+
1389+
let timestamps = [
1390+
0,
1391+
(i64::MAX / 2) as u64,
1392+
i64::MAX as _,
1393+
(i64::MAX as u64) + 1,
1394+
];
1395+
let mut store = timestamps
1396+
.into_iter()
1397+
.map(|timestamp| StoredEvent {
1398+
event: RecordedEvent {
1399+
timestamp,
1400+
..event.clone()
1401+
},
1402+
execution_counter: None,
1403+
})
1404+
.collect();
1405+
1406+
let glean_start_time = glean.start_time();
1407+
glean
1408+
.event_storage()
1409+
.normalize_store(&glean, store_name, &mut store, glean_start_time);
1410+
assert_eq!(4, store.len());
1411+
1412+
assert_eq!(0, store[0].event.timestamp);
1413+
assert_eq!((i64::MAX / 2) as u64, store[1].event.timestamp);
1414+
assert_eq!((i64::MAX as u64), store[2].event.timestamp);
1415+
assert_eq!((i64::MAX as u64), store[3].event.timestamp);
1416+
1417+
let error_count = glean
1418+
.additional_metrics
1419+
.event_timestamp_clamped
1420+
.get_value(&glean, "events");
1421+
assert_eq!(Some(1), error_count);
1422+
}
13601423
}

glean-core/src/internal_metrics.rs

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,10 @@ pub struct AdditionalMetrics {
4040
/// An experimentation identifier derived and provided by the application
4141
/// for the purpose of experimentation enrollment.
4242
pub experimentation_id: StringMetric,
43+
44+
/// The number of times we had to clamp an event timestamp
45+
/// for exceeding the range of a signed 64-bit integer (9223372036854775807).
46+
pub event_timestamp_clamped: CounterMetric,
4347
}
4448

4549
impl CoreMetrics {
@@ -198,6 +202,15 @@ impl AdditionalMetrics {
198202
disabled: false,
199203
dynamic_label: None,
200204
}),
205+
206+
event_timestamp_clamped: CounterMetric::new(CommonMetricData {
207+
name: "event_timestamp_clamped".into(),
208+
category: "glean.error".into(),
209+
send_in_pings: vec!["events".into(), "health".into()],
210+
lifetime: Lifetime::Ping,
211+
disabled: false,
212+
dynamic_label: None,
213+
}),
201214
}
202215
}
203216
}

0 commit comments

Comments
 (0)