From c2163434dbbc8fc791b99e69a05f95af7cbf5c48 Mon Sep 17 00:00:00 2001
From: Dan J Miller <danjm.com@gmail.com>
Date: Fri, 18 Aug 2023 11:15:45 -0230
Subject: [PATCH] Fix and test log.info calls run for each migration (#20517)

* Fix and test log.info calls run for each migration

In migrator/index.js, log.info is called before an after each migration.
These calls are intended to produce breadcrumbs to be captured by sentry
in cases where errors happen during or shortly after migrations are run.
These calls were not causing any output to the console because the log.setLevel
calls in ui/index.js were setting a 'warn value in local storage that was being
used by logLevel in the background.

This commit fixes the problem by setting the `persist` param of setLevel to
false, so that the background no longer reads the ui's log level.

Tests are added to verify that these logs are captured in sentry breadcrumbs
when there is a migration error due to an invariant state.

* Improve breadcrumb message matching

The test modified in this commit asserts eqaulity of  messages from breadcrumbs
and hard coded expected results. This could cause failures, as sometimes the
messages contain whitespace characters. This commit ensures the assertions only
check that the expected string is within the message string, ignoring extra
characters.
---
 app/scripts/background.js     |  2 +-
 test/e2e/fixture-builder.js   |  7 ++++
 test/e2e/tests/errors.spec.js | 60 +++++++++++++++++++++++++++++++++++
 ui/index.js                   |  2 +-
 4 files changed, 69 insertions(+), 2 deletions(-)

diff --git a/app/scripts/background.js b/app/scripts/background.js
index 7e89ce1c3..aa655e5a4 100644
--- a/app/scripts/background.js
+++ b/app/scripts/background.js
@@ -88,7 +88,7 @@ const metamaskInternalProcessHash = {
 
 const metamaskBlockedPorts = ['trezor-connect'];
 
-log.setDefaultLevel(process.env.METAMASK_DEBUG ? 'debug' : 'info');
+log.setLevel(process.env.METAMASK_DEBUG ? 'debug' : 'info', false);
 
 const platform = new ExtensionPlatform();
 const notificationManager = new NotificationManager();
diff --git a/test/e2e/fixture-builder.js b/test/e2e/fixture-builder.js
index ed3e3aaac..3528ec5aa 100644
--- a/test/e2e/fixture-builder.js
+++ b/test/e2e/fixture-builder.js
@@ -724,6 +724,13 @@ class FixtureBuilder {
     return this;
   }
 
+  withBadPreferencesControllerState() {
+    merge(this.fixture.data, {
+      PreferencesController: 5,
+    });
+    return this;
+  }
+
   withTokensControllerERC20() {
     merge(this.fixture.data.TokensController, {
       tokens: [
diff --git a/test/e2e/tests/errors.spec.js b/test/e2e/tests/errors.spec.js
index 36f1921b3..5c557b256 100644
--- a/test/e2e/tests/errors.spec.js
+++ b/test/e2e/tests/errors.spec.js
@@ -124,6 +124,18 @@ describe('Sentry errors', function () {
       });
   }
 
+  async function mockSentryInvariantMigrationError(mockServer) {
+    return await mockServer
+      .forPost('https://sentry.io/api/0000000/envelope/')
+      .withBodyIncluding('typeof state.PreferencesController is number')
+      .thenCallback(() => {
+        return {
+          statusCode: 200,
+          json: {},
+        };
+      });
+  }
+
   async function mockSentryTestError(mockServer) {
     return await mockServer
       .forPost('https://sentry.io/api/0000000/envelope/')
@@ -307,6 +319,54 @@ describe('Sentry errors', function () {
       );
     });
 
+    it('should capture migration log breadcrumbs when there is an invariant state error in a migration', async function () {
+      await withFixtures(
+        {
+          fixtures: {
+            ...new FixtureBuilder()
+              .withMetaMetricsController({
+                metaMetricsId: 'fake-metrics-id',
+                participateInMetaMetrics: true,
+              })
+              .withBadPreferencesControllerState()
+              .build(),
+          },
+          ganacheOptions,
+          title: this.test.title,
+          failOnConsoleError: false,
+          testSpecificMock: mockSentryInvariantMigrationError,
+        },
+        async ({ driver, mockedEndpoint }) => {
+          await driver.navigate();
+
+          // Wait for Sentry request
+          await driver.wait(async () => {
+            const isPending = await mockedEndpoint.isPending();
+            return isPending === false;
+          }, 3000);
+
+          const [mockedRequest] = await mockedEndpoint.getSeenRequests();
+          const mockTextBody = mockedRequest.body.text.split('\n');
+          const mockJsonBody = JSON.parse(mockTextBody[2]);
+          const breadcrumbs = mockJsonBody?.breadcrumbs ?? [];
+          const migrationLogBreadcrumbs = breadcrumbs.filter((breadcrumb) => {
+            return breadcrumb.message?.match(/Running migration \d+/u);
+          });
+          const migrationLogMessages = migrationLogBreadcrumbs.map(
+            (breadcrumb) =>
+              breadcrumb.message.match(/(Running migration \d+)/u)[1],
+          );
+          const firstMigrationLog = migrationLogMessages[0];
+          const lastMigrationLog =
+            migrationLogMessages[migrationLogMessages.length - 1];
+
+          assert.equal(migrationLogMessages.length, 8);
+          assert.equal(firstMigrationLog, 'Running migration 75');
+          assert.equal(lastMigrationLog, 'Running migration 82');
+        },
+      );
+    });
+
     it('should send error events in UI', async function () {
       await withFixtures(
         {
diff --git a/ui/index.js b/ui/index.js
index de1432a80..208006de1 100644
--- a/ui/index.js
+++ b/ui/index.js
@@ -27,7 +27,7 @@ import Root from './pages';
 import txHelper from './helpers/utils/tx-helper';
 import { _setBackgroundConnection } from './store/action-queue';
 
-log.setLevel(global.METAMASK_DEBUG ? 'debug' : 'warn');
+log.setLevel(global.METAMASK_DEBUG ? 'debug' : 'warn', false);
 
 let reduxStore;