Fix extractGeckoLogs for structured Log marker format (bug 2022540) (#5927)

Bug 2022540 switched Log markers from {module, name} fields to structured
{level, message} fields, with the module name stored as the marker name.
The old format used a single module string that could include the log level
prefix (e.g. D/cubeb); the new format uses an integer level field.

Profiles use one format exclusively, never a mix. We detect which by
checking the first Log marker found in each thread.

Co-authored-by: Nazım Can Altınova <canaltinova@gmail.com>

Author: padenot

src/test/unit/window-console.test.ts

@@ -112,6 +112,56 @@ describe('console-accessible values on the window object', function () {
     `);
   });
 
+  it('can extract gecko logs in new structured format', function () {
+    const profile = getProfileWithMarkers([
+      [
+        'nsHttp',
+        170,
+        null,
+        {
+          type: 'Log',
+          level: 1,
+          message:
+            'ParentChannelListener::ParentChannelListener [this=7fb5e19b98d0]',
+        },
+      ],
+      [
+        'nsJarProtocol',
+        190,
+        null,
+        {
+          type: 'Log',
+          level: 2,
+          message: 'nsJARChannel::nsJARChannel [this=0x87f1ec80]\n',
+        },
+      ],
+      ['cubeb', 200, null, { type: 'Log', level: 3, message: 'cubeb_init' }],
+      [
+        'AudioStream',
+        210,
+        null,
+        { type: 'Log', level: 4, message: 'AudioStream init\n' },
+      ],
+      [
+        'VideoSink',
+        220,
+        null,
+        { type: 'Log', level: 5, message: 'VideoSink::VideoSink' },
+      ],
+    ]);
+    const store = storeWithProfile(profile);
+    const target: MixedObject = {};
+    addDataToWindowObject(store.getState, store.dispatch, target);
+    const result = (target as any).extractGeckoLogs();
+    expect(result).toBe(stripIndent`
+      1970-01-01 00:00:00.170000000 UTC - [Unknown Process 0: Empty]: E/nsHttp ParentChannelListener::ParentChannelListener [this=7fb5e19b98d0]
+      1970-01-01 00:00:00.190000000 UTC - [Unknown Process 0: Empty]: W/nsJarProtocol nsJARChannel::nsJARChannel [this=0x87f1ec80]
+      1970-01-01 00:00:00.200000000 UTC - [Unknown Process 0: Empty]: I/cubeb cubeb_init
+      1970-01-01 00:00:00.210000000 UTC - [Unknown Process 0: Empty]: D/AudioStream AudioStream init
+      1970-01-01 00:00:00.220000000 UTC - [Unknown Process 0: Empty]: V/VideoSink VideoSink::VideoSink
+    `);
+  });
+
   describe('totalMarkerDuration', function () {
     function setup(): ExtraPropertiesOnWindowForConsole {
       jest.spyOn(console, 'log').mockImplementation(() => {});

src/types/markers.ts

@@ -634,11 +634,17 @@ export type ChromeEventPayload = {
  * Gecko includes rich log information. This marker payload is used to mirror that
  * log information in the profile.
  */
-export type LogMarkerPayload = {
-  type: 'Log';
-  name: string;
-  module: string;
-};
+export type LogMarkerPayload =
+  | {
+      type: 'Log';
+      name: string;
+      module: string;
+    }
+  | {
+      type: 'Log';
+      level: number;
+      message: string;
+    };
 
 export type DOMEventMarkerPayload = {
   type: 'DOMEvent';

src/utils/window-console.ts

@@ -9,6 +9,7 @@ import type {
   Profile,
   Thread,
   Marker,
+  LogMarkerPayload,
 } from 'firefox-profiler/types';
 import { selectorsForConsole } from 'firefox-profiler/selectors';
 import actions from 'firefox-profiler/actions';
@@ -297,36 +298,45 @@ export function addDataToWindowObject(
     const range =
       selectorsForConsole.profile.getPreviewSelectionRange(getState());
 
+    const LOG_LEVEL_LETTER: Record<number, string> = {
+      1: 'E',
+      2: 'W',
+      3: 'I',
+      4: 'D',
+      5: 'V',
+    };
+
     for (const thread of profile.threads) {
       const { markers } = thread;
+
       for (let i = 0; i < markers.length; i++) {
         const startTime = markers.startTime[i];
-        // Note that Log markers are instant markers, so they only have a start time.
         if (
           startTime !== null &&
-          markers.data[i] &&
           markers.data[i]?.type === 'Log' &&
           startTime >= range.start &&
           startTime <= range.end
         ) {
-          const data = markers.data[i];
-          const markerStartTime = markers.startTime[i];
-          if (
-            data &&
-            markerStartTime !== null &&
-            (data as any).module &&
-            (data as any).name
-          ) {
-            const strTimestamp = d2s(profile.meta.startTime + markerStartTime);
-            const processName = thread.processName ?? 'Unknown Process';
-
-            // The log module may contain the log level for profiles captured after bug 1995503.
-            // If the log module does not contain /, we fake it to D/module
-            const logModule = (data as any).module;
-            const prefix = logModule.includes('/') ? '' : 'D/';
-            const statement = `${strTimestamp} - [${processName} ${thread.pid}: ${thread.name}]: ${prefix}${logModule} ${(data as any).name.trim()}`;
-            logs.push(statement);
+          const data = markers.data[i] as LogMarkerPayload;
+          const strTimestamp = d2s(profile.meta.startTime + startTime);
+          const processName = thread.processName ?? 'Unknown Process';
+
+          let statement;
+          if ('message' in data) {
+            if (!data.message) {
+              continue;
+            }
+            const moduleName = profile.shared.stringArray[markers.name[i]];
+            const levelLetter = LOG_LEVEL_LETTER[data.level] ?? 'D';
+            statement = `${strTimestamp} - [${processName} ${thread.pid}: ${thread.name}]: ${levelLetter}/${moduleName} ${data.message.trim()}`;
+          } else {
+            if (!data.name) {
+              continue;
+            }
+            const prefix = data.module.includes('/') ? '' : 'D/';
+            statement = `${strTimestamp} - [${processName} ${thread.pid}: ${thread.name}]: ${prefix}${data.module} ${data.name.trim()}`;
           }
+          logs.push(statement);
         }
       }
     }