Merge pull request #799 from brizental/1732294-init-fail

Beatriz Rizental · web-flow · commit 9a5dc95d6e3e · 2021-10-11T13:00:38.000+02:00
Bug 1732294 - If initialization errors Glean doesn't do anything else
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -8,6 +8,9 @@
 
 * [#796](https://github.com/mozilla/glean.js/pull/796): Support setting the `app_channel` metric.
   - As described in ["Release channels"](https://mozilla.github.io/glean/book/reference/general/initializing.html?highlight=channel#release-channels).
+* [#799](https://github.com/mozilla/glean.js/pull/799): Make sure Glean does not do anything else in case initialization errors.
+  - This may happen in case there is an error creating the databases. Mostly an issue on Qt/QML where we use a SQLite database which can throw errors on initialization.
+* [#799](https://github.com/mozilla/glean.js/pull/799): Provide stack traces when logging errors.
 
 # v0.21.1 (2021-09-30)
 
diff --git a/glean/src/cli.ts b/glean/src/cli.ts
@@ -238,10 +238,7 @@ async function run(args: string[]) {
   } catch (err) {
     log(
       LOG_TAG,
-      [
-        "Failed to setup the Glean build environment.\n",
-        JSON.stringify(err)
-      ],
+      ["Failed to setup the Glean build environment.\n", err],
       LoggingLevel.Error
     );
     process.exit(1);
diff --git a/glean/src/core/dispatcher.ts b/glean/src/core/dispatcher.ts
@@ -12,17 +12,17 @@ export const enum DispatcherState {
   //
   // When the dispatcher is in this state it will not enqueue
   // more than `maxPreInitQueueSize` tasks.
-  Uninitialized,
+  Uninitialized = "Uninitialized",
   // There are no commands queued and the dispatcher is idle.
-  Idle,
+  Idle = "Idle",
   // The dispatcher is currently processing queued tasks.
-  Processing,
+  Processing = "Processing",
   // The dispatcher is stopped, tasks queued will not be immediatelly processed.
-  Stopped,
+  Stopped = "Stopped",
   // The dispatcher is shutdown, attempting to queue tasks while in this state is a no-op.
   //
   // This state is irreversible.
-  Shutdown,
+  Shutdown = "Shutdown",
 }
 
 // The possible commands to be processed by the dispatcher.
@@ -40,6 +40,12 @@ const enum Commands {
   //
   // Unless unavoidable, prefer using the normal `Task`.
   PersistentTask = "PersistentTask",
+  // Same as the `Task` command, but only tasks passed to `flushInit` to be perfomed
+  // as the first task ever are considered `InitTask`. This task is special because if
+  // it fails, the dispatcher will not proceed executing any other tasks and will shutdown.
+  //
+  // This command is always followed by a concrete task for the dispatcher to execute.
+  InitTask = "InitTask",
   // The dispatcher should stop executing the queued tasks.
   Stop = "Stop",
   // The dispatcher should stop executing the queued tasks and clear the queue.
@@ -52,17 +58,18 @@ const enum Commands {
 
 // A task the dispatcher knows how to execute.
 type Task = () => Promise<void>;
+type TaskCommands = Commands.Task | Commands.TestTask | Commands.PersistentTask | Commands.InitTask;
 
 // An executable command.
 type Command = {
   task: Task,
-  command: Commands.Task | Commands.PersistentTask,
+  command: Exclude<TaskCommands, Commands.TestTask>,
 } | {
   resolver: (value: void | PromiseLike<void>) => void,
   task: Task,
   command: Commands.TestTask,
 } | {
-  command: Exclude<Commands, Commands.Task | Commands.TestTask | Commands.PersistentTask>,
+  command: Exclude<Commands, TaskCommands>,
 };
 
 /**
@@ -99,12 +106,15 @@ class Dispatcher {
    * Executes a task safely, catching any errors.
    *
    * @param task The  task to execute.
+   * @returns Whether or not the task was executed successfully.
    */
-  private async executeTask(task: Task): Promise<void> {
+  private async executeTask(task: Task): Promise<boolean> {
     try {
       await task();
+      return true;
     } catch(e) {
-      log(this.logTag, ["Error executing task:", JSON.stringify(e)], LoggingLevel.Error);
+      log(this.logTag, ["Error executing task:", e], LoggingLevel.Error);
+      return false;
     }
   }
 
@@ -142,18 +152,32 @@ class Dispatcher {
         this.queue = this.queue.filter(c =>
           [Commands.PersistentTask, Commands.Shutdown].includes(c.command)
         );
-        nextCommand = this.getNextCommand();
-        continue;
+        break;
       case (Commands.TestTask):
         await this.executeTask(nextCommand.task);
         nextCommand.resolver();
-        nextCommand = this.getNextCommand();
-        continue;
+        break;
+      case(Commands.InitTask):
+        const result = await this.executeTask(nextCommand.task);
+        if (!result) {
+          log(
+            this.logTag,
+            [
+              "Error initializing dispatcher, won't execute anything further.",
+              "There might be more error logs above."
+            ],
+            LoggingLevel.Error
+          );
+          this.clear();
+          void this.shutdown();
+        }
+        break;
       case(Commands.PersistentTask):
       case(Commands.Task):
         await this.executeTask(nextCommand.task);
-        nextCommand = this.getNextCommand();
+        break;
       }
+      nextCommand = this.getNextCommand();
     }
   }
 
@@ -277,6 +301,7 @@ class Dispatcher {
    * This is a no-op in case the dispatcher is not in an uninitialized state.
    *
    * @param task Optional task to execute before any of the tasks enqueued prior to init.
+   *        Note: if this task throws, the dispatcher will be shutdown and no other tasks will be executed.
    */
   flushInit(task?: Task): void {
     if (this.state !== DispatcherState.Uninitialized) {
@@ -291,7 +316,7 @@ class Dispatcher {
     if (task) {
       this.launchInternal({
         task,
-        command: Commands.Task
+        command: Commands.InitTask
       }, true);
     }
 
diff --git a/glean/src/core/error/index.ts b/glean/src/core/error/index.ts
@@ -59,14 +59,14 @@ export default class ErrorManager {
    *        prepended to the message.
    * @param numErrors The number of errors of the same type to report.
    */
-  async record (
+  async record(
     metric: MetricType,
     error: ErrorType,
-    message: string,
+    message: unknown,
     numErrors = 1
   ): Promise<void> {
     const errorMetric = getErrorMetricForMetric(metric, error);
-    log(createLogTag(metric), `${metric.baseIdentifier()}: ${message}`);
+    log(createLogTag(metric), [`${metric.baseIdentifier()}:`, message]);
     if (numErrors > 0) {
       await CounterMetricType._private_addUndispatched(errorMetric, numErrors);
     } else {
diff --git a/glean/src/core/log.ts b/glean/src/core/log.ts
@@ -29,13 +29,13 @@ export enum LoggingLevel {
  */
 export default function log(
   modulePath: string,
-  message: string | string[],
+  message: unknown | unknown[],
   level = LoggingLevel.Debug
 ): void {
   const prefix = `(Glean.${modulePath})`;
-  if (typeof message === "string") {
-    console[level](prefix, message);
-  } else {
+  if (Array.isArray(message)) {
     console[level](prefix, ...message);
+  } else {
+    console[level](prefix, message);
   }
 }
diff --git a/glean/src/core/metrics/types/url.ts b/glean/src/core/metrics/types/url.ts
@@ -102,11 +102,7 @@ class UrlMetricType extends MetricType {
         await Context.metricsDatabase.record(this, metric);
       } catch (e) {
         if (e instanceof UrlMetricError) {
-          await Context.errorManager.record(
-            this,
-            e.type,
-            e.message
-          );
+          await Context.errorManager.record(this, e.type, e);
         }
       }
     });
diff --git a/glean/src/core/pings/maker.ts b/glean/src/core/pings/maker.ts
@@ -260,7 +260,7 @@ export async function collectAndStorePing(identifier: string, ping: CommonPingDa
         `Error while attempting to modify ping payload for the "${ping.name}" ping using`,
         `the ${JSON.stringify(CoreEvents.afterPingCollection.registeredPluginIdentifier)} plugin.`,
         "Ping will not be submitted. See more logs below.\n\n",
-        JSON.stringify(e)
+        e
       ],
       LoggingLevel.Error
     );
diff --git a/glean/src/core/storage/utils.ts b/glean/src/core/storage/utils.ts
@@ -85,7 +85,7 @@ export function updateNestedObject(
   } catch(e) {
     log(
       LOG_TAG,
-      ["Error while transforming stored value. Ignoring old value.", JSON.stringify(e)],
+      ["Error while transforming stored value. Ignoring old value.", e],
       LoggingLevel.Error
     );
     target[finalKey] = transformFn(undefined);
diff --git a/glean/src/core/upload/index.ts b/glean/src/core/upload/index.ts
@@ -272,14 +272,7 @@ class PingUploader implements PingsDatabaseObserver {
         finalPing.headers
       );
     } catch(e) {
-      log(
-        LOG_TAG,
-        [
-          "Error trying to build ping request:",
-          (e as Error).message
-        ],
-        LoggingLevel.Warn
-      );
+      log(LOG_TAG, [ "Error trying to build ping request:", e ], LoggingLevel.Warn);
       // An unrecoverable failure will make sure the offending ping is removed from the queue and
       // deleted from the database, which is what we want here.
       return new UploadResult(UploadResultStatus.RecoverableFailure);
diff --git a/glean/src/platform/qt/storage.ts b/glean/src/platform/qt/storage.ts
@@ -132,7 +132,7 @@ class QMLStore implements Store {
     } catch(e) {
       log(
         this.logTag,
-        ["Error while attempting to access LocalStorage.\n", JSON.stringify(e)],
+        ["Error while attempting to access LocalStorage.\n", e],
         LoggingLevel.Debug
       );
     } finally {
@@ -155,7 +155,7 @@ class QMLStore implements Store {
       } catch (e) {
         log(
           this.logTag,
-          [`Error executing LocalStorage query: ${query}.\n`, JSON.stringify(e)],
+          [`Error executing LocalStorage query: ${query}.\n`, e],
           LoggingLevel.Debug
         );
         reject();
@@ -190,10 +190,7 @@ class QMLStore implements Store {
     try {
       return getValueFromNestedObject(obj, index);
     } catch(e) {
-      log(this.logTag, [
-        "Error getting value from database.",
-        JSON.stringify((e as Error).message)
-      ]);
+      log(this.logTag, ["Error getting value from database.", e]);
     }
   }
 
diff --git a/glean/src/platform/test/storage.ts b/glean/src/platform/test/storage.ts
@@ -52,7 +52,11 @@ class MockStore implements Store {
     try {
       globalStore = deleteKeyFromNestedObject(globalStore, [ this.rootKey, ...index ]);
     } catch (e) {
-      log(LOG_TAG, [(e as Error).message, "Ignoring."], LoggingLevel.Warn);
+      log(
+        LOG_TAG,
+        [`Error attempting to delete key ${index.toString()} from storage. Ignoring.`, e],
+        LoggingLevel.Warn
+      );
     }
     return Promise.resolve();
   }
diff --git a/glean/src/platform/webext/storage.ts b/glean/src/platform/webext/storage.ts
@@ -155,7 +155,11 @@ class WebExtStore implements Store {
       );
       return this.store.set(query);
     } catch(e) {
-      log(this.logTag, ["Ignoring key", JSON.stringify(e)], LoggingLevel.Warn);
+      log(
+        this.logTag,
+        [`Error attempting to delete key ${index.toString()} from storage. Ignoring.`, e],
+        LoggingLevel.Warn
+      );
     }
   }
 }
diff --git a/glean/src/platform/webext/uploader.ts b/glean/src/platform/webext/uploader.ts
@@ -29,17 +29,17 @@ class BrowserUploader extends Uploader {
       // If we time out and call controller.abort,
       // the fetch API will throw a DOMException with name "AbortError".
       if (e instanceof DOMException) {
-        log(LOG_TAG, ["Timeout while attempting to upload ping.\n", e.message], LoggingLevel.Error);
+        log(LOG_TAG, ["Timeout while attempting to upload ping.\n", e], LoggingLevel.Error);
       } else if (e instanceof TypeError) {
         // From MDN: "A fetch() promise will reject with a TypeError
         // when a network error is encountered or CORS is misconfigured on the server-side,
         // although this usually means permission issues or similar"
         // See: https://developer.mozilla.org/en-US/docs/Web/API/Fetch_API/Using_Fetch#checking_that_the_fetch_was_successful
         //
         // We will treat this as we treat server / network errors in this case.
-        log(LOG_TAG, ["Network error while attempting to upload ping.\n", e.message], LoggingLevel.Error);
+        log(LOG_TAG, ["Network error while attempting to upload ping.\n", e], LoggingLevel.Error);
       } else {
-        log(LOG_TAG, ["Unknown error while attempting to upload ping.\n", JSON.stringify(e)], LoggingLevel.Error);
+        log(LOG_TAG, ["Unknown error while attempting to upload ping.\n", e], LoggingLevel.Error);
       }
 
       clearTimeout(timeout);
diff --git a/glean/tests/integration/schema/schema.spec.ts b/glean/tests/integration/schema/schema.spec.ts
@@ -30,7 +30,12 @@ function fetchSchema(): Promise<JSONObject> {
       });
 
       response.on("end", () => {
-        resolve(JSON.parse(data));
+        try {
+          resolve(JSON.parse(data));
+        } catch(e) {
+          console.error("Data received from the GLEAN_SCHEMA_URL is not valid JSON.\n\n", data);
+          reject();
+        }
       });
     }).on("error", (err) => {
       reject(err);
diff --git a/glean/tests/unit/core/dispatcher.spec.ts b/glean/tests/unit/core/dispatcher.spec.ts
@@ -529,4 +529,28 @@ describe("Dispatcher", function() {
     assert.strictEqual(preShutdownStub.callCount, 10);
     assert.strictEqual(postShutdownStub.callCount, 0);
   });
+
+  it("if init task fails, no other tasks are executed and dispatcher is shutdown", async function () {
+    dispatcher = new Dispatcher();
+
+    const preInitStub = sandbox.stub().callsFake(sampleTask);
+    for (let i = 0; i < 5; i++) {
+      dispatcher.launch(preInitStub);
+    }
+
+    dispatcher.flushInit(() => {
+      throw new Error("Oops.");
+    });
+
+    const postInitStub = sandbox.stub().callsFake(sampleTask);
+    for (let i = 0; i < 5; i++) {
+      dispatcher.launch(postInitStub);
+    }
+
+    await dispatcher.testBlockOnQueue();
+
+    // Check tasks before and after init were not executed, because init task failed.
+    assert.strictEqual(preInitStub.callCount, 0);
+    assert.strictEqual(postInitStub.callCount, 0);
+  });
 });

Original file line number	Diff line number	Diff line change
`@@ -102,11 +102,7 @@ class UrlMetricType extends MetricType {`
`102`	`102`	`await Context.metricsDatabase.record(this, metric);`
`103`	`103`	`} catch (e) {`
`104`	`104`	`if (e instanceof UrlMetricError) {`
`105`		`- await Context.errorManager.record(`
`106`		`- this,`
`107`		`- e.type,`
`108`		`- e.message`
`109`		`- );`
	`105`	`+ await Context.errorManager.record(this, e.type, e);`
`110`	`106`	`}`
`111`	`107`	`}`
`112`	`108`	`});`