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

@@ -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();

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: [

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(
         {

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;