feat: introduce step level tracing

NOTICE.txt

@@ -219,3 +219,32 @@ This product relies on `expect`
  *
  */
 ---------------------------------------------------------------------------
+This product relies on `ChromeDevTools/devtools-frontend`
+
+// Copyright 2014 The Chromium Authors. All rights reserved.
+//
+// Redistribution and use in source and binary forms, with or without
+// modification, are permitted provided that the following conditions are
+// met:
+//
+//    * Redistributions of source code must retain the above copyright
+// notice, this list of conditions and the following disclaimer.
+//    * Redistributions in binary form must reproduce the above
+// copyright notice, this list of conditions and the following disclaimer
+// in the documentation and/or other materials provided with the
+// distribution.
+//    * Neither the name of Google Inc. nor the names of its
+// contributors may be used to endorse or promote products derived from
+// this software without specific prior written permission.
+//
+// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
+// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
+// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
+// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
+// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
+// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
+// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
+// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.

__tests__/cli.test.ts

@@ -268,7 +268,7 @@ describe('CLI', () => {
       .run();
     await cli.waitFor('step/end');
     const output = JSON.parse(cli.output());
-    expect(output.payload.metrics).toBeDefined();
+    expect(output.payload.pagemetrics).toBeDefined();
     expect(await cli.exitCode).toBe(0);
   });
 

__tests__/core/gatherer.test.ts

@@ -25,7 +25,6 @@
 
 import { Gatherer } from '../../src/core/gatherer';
 import { PluginManager } from '../../src/plugins';
-import { NetworkManager } from '../../src/plugins/network';
 import { wsEndpoint } from '../utils/test-config';
 
 jest.mock('../../src/plugins/network');
@@ -51,7 +50,7 @@ describe('Gatherer', () => {
       network: true,
     });
     expect(pluginManager).toBeInstanceOf(PluginManager);
-    const network = pluginManager.get(NetworkManager);
+    const network = pluginManager.get('network');
     expect(network.start).toHaveBeenCalled();
     await Gatherer.stop();
   });

__tests__/core/runner.test.ts

@@ -178,7 +178,7 @@ describe('runner', () => {
     expect(result).toEqual([
       {
         status: 'succeeded',
-        metrics: expect.any(Object),
+        pagemetrics: expect.any(Object),
         url: server.TEST_PAGE,
       },
     ]);
@@ -625,4 +625,34 @@ describe('runner', () => {
     const blobs = screenshotDocs.map(data => data.blob);
     expect(blobs[0]).not.toEqual(blobs[1]);
   });
+
+  it('run - capture trace step level', async () => {
+    const j1 = journey('test trace', async ({ page }) => {
+      step('without FCP', async () => {
+        await page.goto('about:blank');
+      });
+      step('with FCP', async () => {
+        await page.goto(server.TEST_PAGE);
+        // Image paint triggers FCP and LCP
+        await page.setContent(`
+          <img src=${server.PREFIX}/favicon.png>
+        `);
+        await page.waitForLoadState('networkidle');
+      });
+    });
+    const runOptions = { trace: true };
+    const context = await Runner.createContext(runOptions);
+    await runner.registerJourney(j1, context);
+    const [step1, step2] = await runner.runSteps(j1, context, runOptions);
+    await Gatherer.stop();
+    expect(step1.metrics).toBeUndefined();
+    expect(step1.traces).toBeUndefined();
+    expect(step2.traces.length).toBeGreaterThan(0);
+    expect(step2.metrics).toMatchObject({
+      cls: 0,
+      fcp: {
+        us: expect.any(Number),
+      },
+    });
+  });
 });

__tests__/plugins/browser-console.test.ts

@@ -38,8 +38,9 @@ describe('BrowserConsole', () => {
   });
 
   it('should capture browser console logs', async () => {
-    const { page } = await Gatherer.setupDriver({ wsEndpoint });
-    const browserConsole = new BrowserConsole(page);
+    const driver = await Gatherer.setupDriver({ wsEndpoint });
+    const browserConsole = new BrowserConsole(driver);
+    const { page } = driver;
     browserConsole.start();
     await page.goto(server.TEST_PAGE);
     browserConsole._currentStep = { name: 'step-name', index: 0 };

__tests__/plugins/network.test.ts

@@ -24,7 +24,7 @@
  */
 
 import { Gatherer } from '../../src/core/gatherer';
-import { NetworkManager } from '../../src/plugins/network';
+import { NetworkManager, calculateTimings } from '../../src/plugins/network';
 import { Server } from '../utils/server';
 import { wsEndpoint } from '../utils/test-config';
 
@@ -41,8 +41,8 @@ describe('network', () => {
 
   it('should capture network info', async () => {
     const driver = await Gatherer.setupDriver({ wsEndpoint });
-    const network = new NetworkManager();
-    await network.start(driver.client);
+    const network = new NetworkManager(driver);
+    await network.start();
     await driver.page.goto(server.TEST_PAGE);
     const netinfo = await network.stop();
     expect(netinfo.length).toBeGreaterThan(0);
@@ -66,8 +66,8 @@ describe('network', () => {
 
   it('not include data URL in network info', async () => {
     const driver = await Gatherer.setupDriver({ wsEndpoint });
-    const network = new NetworkManager();
-    await network.start(driver.client);
+    const network = new NetworkManager(driver);
+    await network.start();
     await driver.page.goto('data:text/html,<title>Data URI test</title>');
     const netinfo = await network.stop();
     expect(await driver.page.content()).toContain('Data URI test');
@@ -77,8 +77,8 @@ describe('network', () => {
 
   it('produce distinct events for redirects', async () => {
     const driver = await Gatherer.setupDriver({ wsEndpoint });
-    const network = new NetworkManager();
-    await network.start(driver.client);
+    const network = new NetworkManager(driver);
+    await network.start();
     /**
      * Set up two level of redirects
      */
@@ -98,8 +98,8 @@ describe('network', () => {
 
   it('measure resource and transfer size', async () => {
     const driver = await Gatherer.setupDriver({ wsEndpoint });
-    const network = new NetworkManager();
-    await network.start(driver.client);
+    const network = new NetworkManager(driver);
+    await network.start();
     server.route('/route1', (_, res) => {
       res.end('A'.repeat(10));
     });
@@ -114,8 +114,8 @@ describe('network', () => {
 
   it('timings for aborted requests', async () => {
     const driver = await Gatherer.setupDriver({ wsEndpoint });
-    const network = new NetworkManager();
-    await network.start(driver.client);
+    const network = new NetworkManager(driver);
+    await network.start();
 
     const delayTime = 20;
     server.route('/delay100', async (req, res) => {
@@ -144,8 +144,8 @@ describe('network', () => {
 
   it('timings for chunked response', async () => {
     const driver = await Gatherer.setupDriver({ wsEndpoint });
-    const network = new NetworkManager();
-    await network.start(driver.client);
+    const network = new NetworkManager(driver);
+    await network.start();
 
     const delayTime = 100;
     server.route('/chunked', async (req, res) => {
@@ -204,9 +204,8 @@ describe('network', () => {
     };
 
     it('calculate timings for a request event', () => {
-      const network = new NetworkManager();
       const record = getEvent();
-      const timings = network.calculateTimings(record as any);
+      const timings = calculateTimings(record as any);
       expect(timings).toEqual({
         blocked: 0.09999999999998899,
         queueing: -1,
@@ -222,13 +221,12 @@ describe('network', () => {
     });
 
     it('when some resource timing data is unavailable', () => {
-      const network = new NetworkManager();
       const record = getEvent();
       Object.assign(record.response.timing, {
         connectEnd: -1,
         dnsStart: -1,
       });
-      const timings = network.calculateTimings(record as any);
+      const timings = calculateTimings(record as any);
       expect(timings).toEqual({
         blocked: 26.00000000000002,
         connect: -1,
@@ -244,10 +242,9 @@ describe('network', () => {
     });
 
     it('when complete resource timing is not available', () => {
-      const network = new NetworkManager();
       const record = getEvent();
       record.response.timing = null;
-      const timings = network.calculateTimings(record as any);
+      const timings = calculateTimings(record as any);
       expect(timings).toEqual({
         blocked: 1000,
         connect: -1,

__tests__/plugins/performance.test.ts

@@ -39,7 +39,7 @@ describe('performance', () => {
 
   it('should capture page metrics', async () => {
     const driver = await Gatherer.setupDriver({ wsEndpoint });
-    const performance = new PerformanceManager(driver.client);
+    const performance = new PerformanceManager(driver);
     await performance.start();
     await driver.page.goto(server.TEST_PAGE);
     const metrics = await performance.getMetrics();

__tests__/plugins/plugin-manager.test.ts

@@ -31,22 +31,29 @@ jest.mock('../../src/plugins/network');
 describe('plugin manager', () => {
   const pluginManager = new PluginManager({} as any);
 
-  it('start plugin with given type', async () => {
-    await pluginManager.start('network');
-    const instance = pluginManager.get(NetworkManager);
-    expect(instance.start).toHaveBeenCalled();
+  it('register plugin by type', async () => {
+    await pluginManager.register('network', {});
+    const instance = pluginManager.get('network');
+    expect(instance).toBeInstanceOf(NetworkManager);
   });
 
-  it('get returns plugin instance', async () => {
-    await pluginManager.start('network');
-    const instance = pluginManager.get(NetworkManager);
-    expect(instance).toBeInstanceOf(NetworkManager);
+  it('register and unregister all Plugins', async () => {
+    pluginManager.registerAll({});
+    expect(pluginManager.get('network')).toBeDefined();
+    pluginManager.unregisterAll();
+    expect(pluginManager.get('network')).not.toBeDefined();
+  });
+
+  it('start plugin with given type', async () => {
+    await pluginManager.register('network', {}).start();
+    const instance = pluginManager.get('network');
+    expect(instance.start).toHaveBeenCalled();
   });
 
-  it('stop plugin on output generation', async () => {
-    await pluginManager.start('network');
-    const instance = pluginManager.get(NetworkManager);
-    await pluginManager.output();
+  it('stop plugin by type', async () => {
+    await pluginManager.register('network', {}).start();
+    const instance = pluginManager.get('network');
+    await pluginManager.stop('network');
     expect(instance.start).toHaveBeenCalled();
     expect(instance.stop).toHaveBeenCalled();
   });

__tests__/plugins/tracing.test.ts

@@ -37,25 +37,19 @@ describe('tracing', () => {
     await server.close();
   });
 
-  it('should capture filmstrips', async () => {
+  it('capture filmstrips', async () => {
     const driver = await Gatherer.setupDriver({ wsEndpoint });
-    const tracer = new Tracing({ filmstrips: true, trace: true });
-    await tracer.start(driver.client);
+    const tracer = new Tracing(driver, { filmstrips: true });
+    await tracer.start();
     await driver.page.goto(server.TEST_PAGE);
-    await driver.page.waitForLoadState();
-    const { filmstrips, traces } = await tracer.stop(driver.client);
+    await driver.page.waitForLoadState('load');
+    const { filmstrips } = await tracer.stop();
     await Gatherer.stop();
     expect(filmstrips.length).toBeGreaterThan(0);
     expect(filmstrips[0]).toMatchObject({
       blob: expect.any(String),
       mime: 'image/jpeg',
       start: { us: expect.any(Number) },
     });
-    expect(traces.length).toBeGreaterThan(0);
-    expect(traces[0]).toMatchObject({
-      name: 'navigationStart',
-      type: 'mark',
-      start: { us: expect.any(Number) },
-    });
   });
 });

__tests__/reporters/__snapshots__/json.test.ts.snap

@@ -349,13 +349,13 @@ exports[`json reporter screenshots write block & reference docs 1`] = `
 exports[`json reporter writes each step as NDJSON to the FD 1`] = `
 "{\\"type\\":\\"journey/register\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"root_fields\\":{\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"package_version\\":\\"0.0.1\\"}
 {\\"type\\":\\"journey/start\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"root_fields\\":{\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"payload\\":{\\"params\\":{\\"environment\\":\\"testing\\"},\\"source\\":\\"() => { }\\"},\\"package_version\\":\\"0.0.1\\"}
+{\\"type\\":\\"step/metrics\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"step\\":{\\"name\\":\\"s1\\",\\"index\\":1},\\"root_fields\\":{\\"browser\\":{\\"relative_trace\\":{\\"name\\":\\"navigationStart\\",\\"type\\":\\"mark\\",\\"start\\":{\\"us\\":3065705158085}}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"package_version\\":\\"0.0.1\\"}
+{\\"type\\":\\"step/metrics\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"step\\":{\\"name\\":\\"s1\\",\\"index\\":1},\\"root_fields\\":{\\"browser\\":{\\"relative_trace\\":{\\"name\\":\\"firstContentfulPaint\\",\\"type\\":\\"mark\\",\\"start\\":{\\"us\\":3065705560142}}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"package_version\\":\\"0.0.1\\"}
+{\\"type\\":\\"step/metrics\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"step\\":{\\"name\\":\\"s1\\",\\"index\\":1},\\"root_fields\\":{\\"browser\\":{\\"relative_trace\\":{\\"name\\":\\"layoutShift\\",\\"type\\":\\"mark\\",\\"start\\":{\\"us\\":463045197179},\\"score\\":0.19932291666666668}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"package_version\\":\\"0.0.1\\"}
+{\\"type\\":\\"step/metrics\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"step\\":{\\"name\\":\\"s1\\",\\"index\\":1},\\"root_fields\\":{\\"browser\\":{\\"experience\\":{\\"lcp\\":{\\"us\\":200},\\"fcp\\":{\\"us\\":100},\\"dcl\\":{\\"us\\":300},\\"load\\":{\\"us\\":400},\\"cls\\":0.123}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"package_version\\":\\"0.0.1\\"}
+{\\"type\\":\\"step/filmstrips\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"step\\":{\\"name\\":\\"s1\\",\\"index\\":1},\\"root_fields\\":{\\"browser\\":{\\"relative_trace\\":{\\"start\\":{\\"us\\":392583998697}}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"payload\\":{\\"index\\":0},\\"blob\\":\\"dummy\\",\\"blob_mime\\":\\"image/jpeg\\",\\"package_version\\":\\"0.0.1\\"}
 {\\"type\\":\\"step/end\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"step\\":{\\"name\\":\\"s1\\",\\"index\\":1,\\"status\\":\\"succeeded\\",\\"duration\\":{\\"us\\":10000000}},\\"root_fields\\":{\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"payload\\":{\\"source\\":\\"() => { }\\",\\"url\\":\\"dummy\\",\\"status\\":\\"succeeded\\"},\\"url\\":\\"dummy\\",\\"package_version\\":\\"0.0.1\\"}
 {\\"type\\":\\"journey/network_info\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"root_fields\\":{\\"user_agent\\":{},\\"http\\":{\\"request\\":{\\"body\\":{\\"bytes\\":0,\\"content\\":\\"\\"}}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"payload\\":{\\"browser\\":{},\\"is_navigation_request\\":true},\\"package_version\\":\\"0.0.1\\"}
-{\\"type\\":\\"journey/filmstrips\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"root_fields\\":{\\"browser\\":{\\"relative_trace\\":{\\"start\\":{\\"us\\":392583998697}}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"payload\\":{\\"index\\":0},\\"blob\\":\\"dummy\\",\\"blob_mime\\":\\"image/jpeg\\",\\"package_version\\":\\"0.0.1\\"}
-{\\"type\\":\\"journey/metrics\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"root_fields\\":{\\"browser\\":{\\"relative_trace\\":{\\"name\\":\\"navigationStart\\",\\"type\\":\\"mark\\",\\"start\\":{\\"us\\":3065705158085}}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"package_version\\":\\"0.0.1\\"}
-{\\"type\\":\\"journey/metrics\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"root_fields\\":{\\"browser\\":{\\"relative_trace\\":{\\"name\\":\\"firstContentfulPaint\\",\\"type\\":\\"mark\\",\\"start\\":{\\"us\\":3065705560142}}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"package_version\\":\\"0.0.1\\"}
-{\\"type\\":\\"journey/metrics\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"root_fields\\":{\\"browser\\":{\\"relative_trace\\":{\\"name\\":\\"layoutShift\\",\\"type\\":\\"mark\\",\\"start\\":{\\"us\\":463045197179},\\"score\\":0.19932291666666668}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"package_version\\":\\"0.0.1\\"}
-{\\"type\\":\\"journey/metrics\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\"},\\"root_fields\\":{\\"browser\\":{\\"experience\\":{\\"lcp\\":{\\"us\\":200},\\"fcp\\":{\\"us\\":100},\\"dcl\\":{\\"us\\":300},\\"load\\":{\\"us\\":400},\\"cls\\":0.123}},\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"package_version\\":\\"0.0.1\\"}
 {\\"type\\":\\"journey/end\\",\\"@timestamp\\":1600300800000000,\\"journey\\":{\\"name\\":\\"j1\\",\\"id\\":\\"j1\\",\\"status\\":\\"succeeded\\"},\\"root_fields\\":{\\"os\\":{\\"platform\\":\\"darwin\\"},\\"package\\":{\\"name\\":\\"@elastic/synthetics\\",\\"version\\":\\"0.0.1\\"}},\\"payload\\":{\\"start\\":0,\\"end\\":11,\\"status\\":\\"succeeded\\"},\\"package_version\\":\\"0.0.1\\"}
 "
 `;

__tests__/reporters/json.test.ts

@@ -118,13 +118,6 @@ describe('json reporter', () => {
       url: 'dummy',
       start: 0,
       end: 10,
-    });
-    runner.emit('journey:end', {
-      journey: j1,
-      status: 'succeeded',
-      start: 0,
-      end: 11,
-      options: {},
       filmstrips: [
         {
           blob: 'dummy',
@@ -134,14 +127,6 @@ describe('json reporter', () => {
           },
         },
       ],
-      networkinfo: [
-        {
-          request: {},
-          response: undefined,
-          isNavigationRequest: true,
-          browser: {},
-        } as any,
-      ],
       traces: [
         {
           name: 'navigationStart',
@@ -174,6 +159,21 @@ describe('json reporter', () => {
         cls: 0.123,
       },
     });
+    runner.emit('journey:end', {
+      journey: j1,
+      status: 'succeeded',
+      start: 0,
+      end: 11,
+      options: {},
+      networkinfo: [
+        {
+          request: {},
+          response: undefined,
+          isNavigationRequest: true,
+          browser: {},
+        } as any,
+      ],
+    });
     runner.emit('end', 'done');
     expect((await readAndCloseStream()).toString()).toMatchSnapshot();
   });