Merge pull request #1452 from rosahbruno/1723090-delete-trailing-restart-events

Bug 1723090 - Delete trailing glean.restarted events

Author: rosahbruno

CHANGELOG.md

@@ -2,6 +2,7 @@
 
 [Full changelog](https://github.com/mozilla/glean.js/compare/v1.1.0...main)
 
+* [#1452](https://github.com/mozilla/glean.js/pull/1452): Remove `glean.restarted` trailing events from events list.
 * [#1450](https://github.com/mozilla/glean.js/pull/1450): Update `ts-node` to 10.8.0 to resolve ESM issues when running tests.
 * [#1449](https://github.com/mozilla/glean.js/pull/1449): BUGFIX: Add missing quotes to `prepare-release` script to fix issues with version numbers in Qt sample README & circle ci config.
 * [#1449](https://github.com/mozilla/glean.js/pull/1449): Update Qt sample project docs to include note about problems with different version numbers of Qt commands.

docs/reference/metrics.md

@@ -25,7 +25,7 @@ In addition to those built-in metrics, the following metrics are added to the pi
 | glean.error.invalid_overflow |[labeled_counter](https://mozilla.github.io/glean/book/user/metrics/labeled_counters.html) |Counts the number of times a metric was set a value that overflowed. The labels are the `category.name` identifier of the metric.  |[Bug 1591912](https://bugzilla.mozilla.org/show_bug.cgi?id=1591912#c3)||never |1 |
 | glean.error.invalid_state |[labeled_counter](https://mozilla.github.io/glean/book/user/metrics/labeled_counters.html) |Counts the number of times a timing metric was used incorrectly. The labels are the `category.name` identifier of the metric.  |[Bug 1499761](https://bugzilla.mozilla.org/show_bug.cgi?id=1499761#c5)||never |1 |
 | glean.error.invalid_value |[labeled_counter](https://mozilla.github.io/glean/book/user/metrics/labeled_counters.html) |Counts the number of times a metric was set to an invalid value. The labels are the `category.name` identifier of the metric.  |[Bug 1499761](https://bugzilla.mozilla.org/show_bug.cgi?id=1499761#c5)||never |1 |
-| glean.restarted |[event](https://mozilla.github.io/glean/book/user/metrics/event.html) |Event that signals an application restart.  **This event is included in all pings (custom or otherwise) that contain events.**  |[mozilla/glean.js#526](https://github.com/mozilla/glean.js/pull/526#issuecomment-889892100)||never |1 |
+| glean.restarted |[event](https://mozilla.github.io/glean/book/user/metrics/event.html) |Event that signals an application restart, leading and trailing restarted events will be omitted. **This event is included in all pings (custom or otherwise) that contain events.**  |[mozilla/glean.js#526](https://github.com/mozilla/glean.js/pull/526#issuecomment-889892100)||never |1 |
 
 ## deletion-request
 

glean/src/core/metrics/events_database/index.ts

@@ -303,7 +303,8 @@ class EventsDatabase {
    * 1. Sorts event by execution counter and timestamp;
    * 2. Applies offset to events timestamps;
    * 3. Removes the first event if it is a `glean.restarted` event;
-   * 4. Removes reserved extra keys and stringifies all extras values.
+   * 4. Removes reserved extra keys and stringifies all extras values;
+   * 5. Removes all trailing `glean.restarted` events (if they exists);
    *
    * @param pingName The name of the ping for which the payload is being prepared.
    * @param pingData An unsorted list of events.
@@ -314,7 +315,7 @@ class EventsDatabase {
     pingData: RecordedEvent[]
   ): Promise<JSONArray> {
     // Sort events by execution counter and by timestamp.
-    const sortedEvents = pingData.sort((a, b) => {
+    let sortedEvents = pingData.sort((a, b) => {
       const executionCounterA = Number(a.get().extra?.[GLEAN_EXECUTION_COUNTER_EXTRA_KEY]);
       const executionCounterB = Number(b.get().extra?.[GLEAN_EXECUTION_COUNTER_EXTRA_KEY]);
       // Sort by execution counter, in case they are different.
@@ -393,6 +394,9 @@ class EventsDatabase {
       });
     }
 
+    // There is no additional context in trailing `glean.restarted` events, they can be removed.
+    sortedEvents = this.removeTrailingRestartedEvents(sortedEvents);
+
     return sortedEvents.map((e) => e.payload());
   }
 
@@ -402,6 +406,30 @@ class EventsDatabase {
   async clearAll(): Promise<void> {
     await this.eventsStore.delete([]);
   }
+
+  private isRestartedEvent(event: RecordedEvent): boolean {
+    // This extra key will only exist for `glean.restarted` events. If at some
+    // point that is no longer the case, this can be updated to check the event
+    // `name` and `category` instead.
+    return !!event?.get()?.extra?.[GLEAN_REFERENCE_TIME_EXTRA_KEY];
+  }
+
+  /**
+   * Removes all trailing `glean.restarted` events. We will continue to check
+   * the last element of the array until there are no longer any elements OR
+   * the event is not a `glean.restarted` event.
+   *
+   * @param sortedEvents Before this is called, events should already be sorted
+   *        which includes removing the leading `glean.restarted` event.
+   * @returns The input array without any trailing `glean.restarted` events.
+   */
+  private removeTrailingRestartedEvents(sortedEvents: RecordedEvent[]): RecordedEvent[] {
+    while (!!sortedEvents.length && this.isRestartedEvent(sortedEvents[sortedEvents.length - 1])) {
+      sortedEvents.pop();
+    }
+
+    return sortedEvents;
+  }
 }
 
 export default EventsDatabase;

glean/src/core/testing/events.ts

@@ -0,0 +1,28 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+import { Context } from "../context.js";
+import EventsDatabase from "../metrics/events_database/index.js";
+
+/**
+ * Test-only API
+ *
+ * Fakes a restart by creating a new instance of the events database which will
+ * log a `glean.restarted` event.
+ *
+ * If you do not move the clock forward, an error will be logged.
+ *
+ * @param timeOffset How far ahead to move clock before restarting. Some events just need
+ *        a future time, others need a specific future time. The default time is 1 minute.
+ * @returns New instance of `EventsDatabase` since we "restarted" it.
+ */
+export async function testRestartGlean(timeOffset: number = 1000 * 60): Promise<EventsDatabase> {
+  // Move the clock to look like Glean was really restarted.
+  Context.startTime.setTime(Context.startTime.getTime() + timeOffset);
+
+  // Fake a restart.
+  const db = new EventsDatabase();
+  await db.initialize();
+  return db;
+}

glean/src/core/testing/index.ts

@@ -29,3 +29,6 @@ export async function testResetGlean(
   await testUninitializeGlean(clearStores);
   await testInitializeGlean(applicationId, uploadEnabled, config);
 }
+
+export * from "./utils.js";
+export * from "./events.js";

glean/tests/unit/core/metrics/events_database.spec.ts

@@ -7,20 +7,29 @@ import type { SinonFakeTimers } from "sinon";
 import sinon from "sinon";
 
 import { Lifetime } from "../../../../src/core/metrics/lifetime";
-import EventsDatabase, { getGleanRestartedEventMetric } from "../../../../src/core/metrics/events_database";
-import { InternalEventMetricType as EventMetricType} from "../../../../src/core/metrics/types/event";
+import EventsDatabase, {
+  getGleanRestartedEventMetric,
+} from "../../../../src/core/metrics/events_database";
+import { InternalEventMetricType as EventMetricType } from "../../../../src/core/metrics/types/event";
 import type { JSONObject } from "../../../../src/core/utils";
 import CounterMetricType from "../../../../src/core/metrics/types/counter";
 import { generateReservedMetricIdentifiers } from "../../../../src/core/metrics/database";
-import { InternalPingType as PingType} from "../../../../src/core/pings/ping_type";
+import { InternalPingType as PingType } from "../../../../src/core/pings/ping_type";
 import { Context } from "../../../../src/core/context";
 import { RecordedEvent } from "../../../../src/core/metrics/events_database/recorded_event";
-import { EVENTS_PING_NAME, GLEAN_EXECUTION_COUNTER_EXTRA_KEY } from "../../../../src/core/constants";
+import {
+  EVENTS_PING_NAME,
+  GLEAN_EXECUTION_COUNTER_EXTRA_KEY,
+} from "../../../../src/core/constants";
 import { collectPing } from "../../../../src/core/pings/maker";
 import { ErrorType } from "../../../../src/core/error/error_type";
 import { testResetGlean } from "../../../../src/core/testing";
 import type { Event } from "../../../../src/core/metrics/events_database/recorded_event";
-import { testInitializeGlean, testUninitializeGlean } from "../../../../src/core/testing/utils";
+import {
+  testInitializeGlean,
+  testRestartGlean,
+  testUninitializeGlean,
+} from "../../../../src/core/testing";
 import { WaitableUploader } from "../../../utils";
 import type { PingPayload } from "../../../../src/core/pings/ping_payload";
 
@@ -334,19 +343,14 @@ describe("EventsDatabase", function() {
     }));
 
     // Move the clock forward by one minute to look like Glean was really restarted.
-    Context.startTime.setTime(Context.startTime.getTime() + 1000 * 60);
-    // Fake a re-start.
-    const db2 = new EventsDatabase();
-    await db2.initialize();
+    const db2 = await testRestartGlean();
 
     for (const store of stores) {
       const snapshot = await db2.getPingEvents(store, true);
       assert.ok(snapshot);
-      assert.strictEqual(2, snapshot.length);
+      assert.strictEqual(1, snapshot.length);
       assert.strictEqual("test", (snapshot[0] as JSONObject)["category"]);
       assert.strictEqual("event_injection", (snapshot[0] as JSONObject)["name"]);
-      assert.strictEqual("glean", (snapshot[1] as JSONObject)["category"]);
-      assert.strictEqual("restarted", (snapshot[1] as JSONObject)["name"]);
 
       // Check that no errors were recorded for the `glean.restarted` metric.
       const restartedMetric = getGleanRestartedEventMetric([store]);
@@ -375,10 +379,7 @@ describe("EventsDatabase", function() {
       }));
 
       // Move the clock forward by one minute.
-      Context.startTime.setTime(Context.startTime.getTime() + 1000 * 60);
-      // Fake a re-start.
-      db = new EventsDatabase();
-      await db.initialize();
+      db = await testRestartGlean();
     }
 
     const snapshot = await db.getPingEvents("store", true);
@@ -396,12 +397,21 @@ describe("EventsDatabase", function() {
       prevTime = e.timestamp;
     }
 
-    // Make sure the found events are the expected events.
+    // Make sure the found events are the expected events. This array consists of
+    // a user created event followed by a restarted event and repeats.
     for (let i = 0; i < 10; i++) {
-      assert.strictEqual("test", (snapshot[i * 2] as JSONObject)["category"]);
-      assert.strictEqual(`stichting_test_${i}`, (snapshot[i * 2] as JSONObject)["name"]);
-      assert.strictEqual("glean", (snapshot[(i * 2) + 1] as JSONObject)["category"]);
-      assert.strictEqual("restarted", (snapshot[(i * 2) + 1] as JSONObject)["name"]);
+      const userEvent = snapshot[i * 2] as JSONObject;
+      const restartedEvent = snapshot[(i * 2) + 1] as JSONObject;
+
+      assert.strictEqual("test", userEvent["category"]);
+      assert.strictEqual(`stichting_test_${i}`, userEvent["name"]);
+
+      // We no longer keep trailing restarted events, so in this scenario, we need to ignore
+      // the final element of the snapshot since it previously had a restarted event.
+      if (restartedEvent) {
+        assert.strictEqual("glean", restartedEvent["category"]);
+        assert.strictEqual("restarted", restartedEvent["name"]);
+      }
 
       // Check that no errors were recorded for the `glean.restarted` metric.
       const restartedMetric = getGleanRestartedEventMetric(["store"]);
@@ -451,12 +461,21 @@ describe("EventsDatabase", function() {
       prevTime = e.timestamp;
     }
 
-    // Make sure the found events are the expected events.
+    // Make sure the found events are the expected events. This array consists of
+    // a user created event followed by a restarted event and repeats.
     for (let i = 0; i < 10; i++) {
-      assert.strictEqual("test", (snapshot[i * 2] as JSONObject)["category"]);
-      assert.strictEqual(`time_travel_${i}`, (snapshot[i * 2] as JSONObject)["name"]);
-      assert.strictEqual("glean", (snapshot[(i * 2) + 1] as JSONObject)["category"]);
-      assert.strictEqual("restarted", (snapshot[(i * 2) + 1] as JSONObject)["name"]);
+      const userEvent = snapshot[i * 2] as JSONObject;
+      const restartedEvent = snapshot[(i * 2) + 1] as JSONObject;
+
+      assert.strictEqual("test", userEvent["category"]);
+      assert.strictEqual(`time_travel_${i}`, userEvent["name"]);
+
+      // We no longer keep trailing restarted events, so in this scenario, we need to ignore
+      // the final element of the snapshot since it previously had a restarted event.
+      if (restartedEvent) {
+        assert.strictEqual("glean", restartedEvent["category"]);
+        assert.strictEqual("restarted", restartedEvent["name"]);
+      }
     }
 
     // Time went backwards, so errors must have been recorded.
@@ -505,12 +524,21 @@ describe("EventsDatabase", function() {
       prevTime = e.timestamp;
     }
 
-    // Make sure the found events are the expected events.
+    // Make sure the found events are the expected events. This array consists of
+    // a user created event followed by a restarted event and repeats.
     for (let i = 0; i < 10; i++) {
-      assert.strictEqual("test", (snapshot[i * 2] as JSONObject)["category"]);
-      assert.strictEqual(`time_travel_${i}`, (snapshot[i * 2] as JSONObject)["name"]);
-      assert.strictEqual("glean", (snapshot[(i * 2) + 1] as JSONObject)["category"]);
-      assert.strictEqual("restarted", (snapshot[(i * 2) + 1] as JSONObject)["name"]);
+      const userEvent = snapshot[i * 2] as JSONObject;
+      const restartedEvent = snapshot[(i * 2) + 1] as JSONObject;
+
+      assert.strictEqual("test", userEvent["category"]);
+      assert.strictEqual(`time_travel_${i}`, userEvent["name"]);
+
+      // We no longer keep trailing restarted events, so in this scenario, we need to ignore
+      // the final element of the snapshot since it previously had a restarted event.
+      if (restartedEvent) {
+        assert.strictEqual("glean", restartedEvent["category"]);
+        assert.strictEqual("restarted", restartedEvent["name"]);
+      }
     }
 
     // Time stood still, so an error must have been recorded.
@@ -552,10 +580,7 @@ describe("EventsDatabase", function() {
 
     // Move the clock forward by one hour.
     const restartedTimeOffset = 1000 * 60 * 60;
-    Context.startTime.setTime(firstStartTime.getTime() + restartedTimeOffset);
-    // Product is rebooted.
-    db = new EventsDatabase();
-    await db.initialize();
+    db = await testRestartGlean(restartedTimeOffset);
 
     // New events are recorded.
     await db.record(event, new RecordedEvent({
@@ -622,10 +647,7 @@ describe("EventsDatabase", function() {
 
     // Move the clock forward by one hour.
     const restartedTimeOffset = 1000 * 60 * 60;
-    Context.startTime.setTime(firstStartTime.getTime() + restartedTimeOffset);
-    // Product is rebooted.
-    db = new EventsDatabase();
-    await db.initialize();
+    db = await testRestartGlean(restartedTimeOffset);
 
     // New set of events are recorded
     await db.record(event, new RecordedEvent({
@@ -640,10 +662,7 @@ describe("EventsDatabase", function() {
     }));
 
     // Move the clock forward by one more hour.
-    Context.startTime.setTime(firstStartTime.getTime() + restartedTimeOffset * 2);
-    // Product is rebooted.
-    db = new EventsDatabase();
-    await db.initialize();
+    db = await testRestartGlean(restartedTimeOffset);
 
     // New set of events are recorded
     await db.record(event, new RecordedEvent({

glean/tests/unit/core/pings/maker.spec.ts

@@ -5,18 +5,23 @@
 import assert from "assert";
 import sinon from "sinon";
 
-import { InternalPingType as PingType} from "../../../../src/core/pings/ping_type";
+import { InternalPingType as PingType } from "../../../../src/core/pings/ping_type";
 import * as PingMaker from "../../../../src/core/pings/maker";
 import Glean from "../../../../src/core/glean";
 import CoreEvents from "../../../../src/core/events";
 import Plugin from "../../../../src/plugins";
-import type { JSONObject } from "../../../../src/core/utils";
+import type { JSONArray, JSONObject } from "../../../../src/core/utils";
 import { Context } from "../../../../src/core/context";
 import { stopGleanUploader } from "../../../utils";
 import EventMetricType from "../../../../src/core/metrics/types/event";
 import { Lifetime } from "../../../../src/core/metrics/lifetime";
-import { testInitializeGlean, testUninitializeGlean } from "../../../../src/core/testing/utils";
-import { testResetGlean } from "../../../../src/core/testing";
+import {
+  testInitializeGlean,
+  testResetGlean,
+  testRestartGlean,
+  testUninitializeGlean,
+} from "../../../../src/core/testing";
+import type { ExtraMap } from "../../../../src/core/metrics/events_database/recorded_event";
 
 const sandbox = sinon.createSandbox();
 
@@ -273,4 +278,47 @@ describe("PingMaker", function() {
       labeled_counter: { "glean.error.invalid_value": { "glean.restarted": 1 } }
     });
   });
+
+  it("should delete trailing restarted events", async function() {
+    const ping = new PingType({
+      name: "aPing",
+      includeClientId: true,
+      sendIfEmpty: true,
+    });
+    const event = new EventMetricType({
+      category: "test",
+      name: "aEvent",
+      sendInPings: ["aPing"],
+      lifetime: Lifetime.Ping,
+      disabled: false
+    });
+
+    const triggerCustomEvent = async (event: EventMetricType<ExtraMap>) => {
+      event.record();
+      // Wait for recording action to complete
+      await event.testGetValue();
+    };
+
+    const triggerRestartedEvent = async () => {
+      await testRestartGlean();
+    };
+
+    // Record events
+    await triggerCustomEvent(event);
+
+    await triggerRestartedEvent();
+    await triggerRestartedEvent();
+    await triggerRestartedEvent();
+
+    await triggerCustomEvent(event);
+
+    await triggerRestartedEvent();
+    await triggerRestartedEvent();
+
+    await PingMaker.collectAndStorePing("ident", ping);
+    const allPings = Object.fromEntries(await Context.pingsDatabase.getAllPings());
+    const eventsArray = allPings["ident"]["payload"]["events"] as JSONArray;
+
+    assert.equal(5, eventsArray.length);
+  });
 });