fix: avoid hanging on capturing network data (elastic#719)

* fix: avoid hanging on capturing network data

* add slow test and fix lint

__tests__/plugins/network.test.ts

@@ -176,6 +176,7 @@ describe('network', () => {
     server.route('/chunked', async (req, res) => {
       await delay(delayTime + 1);
       res.writeHead(200, {
+        'transfer-encoding': 'chunked',
         'content-type': 'application/javascript',
       });
       res.write('a');
@@ -297,6 +298,45 @@ describe('network', () => {
     const netinfo = await network.stop();
     await Gatherer.stop();
     expect(netinfo.length).toBe(0);
-    await Gatherer.dispose(driver);
+  });
+
+  it('do not hang on slow chunked response', async () => {
+    const driver = await Gatherer.setupDriver({
+      wsEndpoint,
+    });
+    const network = new NetworkManager(driver);
+    await network.start();
+
+    server.route('/index', async (req, res) => {
+      res.writeHead(200, {
+        'Content-Type': 'text/html',
+      });
+      res.end(`
+        <script>
+      var delayedPromise = new Promise(r => setTimeout(r, 300));
+      setTimeout(() => {
+        var x = new XMLHttpRequest();
+        x.open("POST", "chunked.txt");
+        x.send(null);
+      }, 0);
+      </script>`);
+    });
+    server.route('/chunked.txt', async (req, res) => {
+      res.writeHead(200, {
+        'Content-Type': 'text/plain',
+        'Transfer-Encoding': 'chunked',
+      });
+      res.write('start');
+      // response is never ended
+    });
+
+    driver.page.on('console', (msg: any) => {
+      console.log('console', msg.text());
+    });
+    await driver.page.goto(server.PREFIX + '/index');
+    await driver.page.evaluate(() => (window as any).delayedPromise);
+    const netinfo = await network.stop();
+    await Gatherer.stop();
+    expect(netinfo.length).toBe(2);
   });
 });

src/core/gatherer.ts

@@ -125,11 +125,13 @@ export class Gatherer {
   }
 
   static async dispose(driver: Driver) {
+    log(`Gatherer: closing all contexts`);
     await driver.request.dispose();
     await driver.context.close();
   }
 
   static async stop() {
+    log(`Gatherer: closing browser`);
     if (Gatherer.browser) {
       await Gatherer.browser.close();
       Gatherer.browser = null;

src/core/logger.ts

@@ -26,13 +26,20 @@
 import { grey, cyan, dim, italic } from 'kleur/colors';
 import { now } from '../helpers';
 
+/**
+ * Set debug based on DEBUG ENV and namespace - synthetics
+ */
+if (process.env.DEBUG && process.env.DEBUG.includes('synthetics')) {
+  process.env['__SYNTHETICS__DEBUG__'] = '1';
+}
+
 export function log(msg) {
-  if (!process.env.DEBUG || !msg) {
+  if (!process.env['__SYNTHETICS__DEBUG__'] || !msg) {
     return;
   }
   if (typeof msg === 'object') {
     msg = JSON.stringify(msg);
   }
   const time = dim(cyan(`at ${parseInt(String(now()))} ms `));
-  console.log(time + italic(grey(msg)) + '\n');
+  console.log(time + italic(grey(msg)));
 }

src/core/runner.ts

@@ -118,6 +118,7 @@ export default class Runner {
         join(Runner.screenshotPath, fileName),
         JSON.stringify(screenshot)
       );
+      log(`Runner: captured screenshot for (${step.name})`);
     }
   }
 

src/options.ts

@@ -29,15 +29,6 @@ import { readConfig } from './config';
 import { getNetworkConditions, DEFAULT_THROTTLING_OPTIONS } from './helpers';
 import type { CliArgs, RunOptions, ThrottlingOptions } from './common_types';
 
-/**
- * Set debug based on DEBUG ENV and -d flags
- * namespace - synthetics
- */
-const namespace = 'synthetics';
-if (process.env.DEBUG && process.env.DEBUG.includes(namespace)) {
-  process.env.DEBUG = '1';
-}
-
 export function normalizeOptions(cliArgs: CliArgs): RunOptions {
   const options: RunOptions = {
     ...cliArgs,

src/plugins/browser-console.ts

@@ -24,6 +24,7 @@
  */
 
 import { BrowserMessage, Driver } from '../common_types';
+import { log } from '../core/logger';
 import { Step } from '../dsl';
 import { getTimestamp } from '../helpers';
 
@@ -76,13 +77,15 @@ export class BrowserConsole {
   }
 
   start() {
+    log(`Plugins: started collecting console events`);
     this.driver.page.on('console', this.consoleEventListener);
     this.driver.page.on('pageerror', this.pageErrorEventListener);
   }
 
   stop() {
     this.driver.page.off('console', this.consoleEventListener);
     this.driver.page.off('pageerror', this.pageErrorEventListener);
+    log(`Plugins: stopped collecting console events`);
     return this.messages;
   }
 }

src/plugins/network.ts

@@ -25,6 +25,7 @@
 
 import { Page, Request, Response } from 'playwright-chromium';
 import { NetworkInfo, BrowserInfo, Driver } from '../common_types';
+import { log } from '../core/logger';
 import { Step } from '../dsl';
 import { getTimestamp } from '../helpers';
 
@@ -77,6 +78,7 @@ export class NetworkManager {
   }
 
   async start() {
+    log(`Plugins: started collecting network events`);
     const { client, context } = this.driver;
     const { product } = await client.send('Browser.getVersion');
     const [name, version] = product.split('/');
@@ -116,7 +118,7 @@ export class NetworkManager {
       request: {
         url,
         method: request.method(),
-        headers: {},
+        headers: request.headers(),
         body: {
           bytes: request.postDataBuffer()?.length || 0,
         },
@@ -168,19 +170,6 @@ export class NetworkManager {
         networkEntry.request.referrer = reqHeaders?.referer;
       })
     );
-    this._addBarrier(
-      page,
-      response.serverAddr().then(server => {
-        networkEntry.response.remoteIPAddress = server?.ipAddress;
-        networkEntry.response.remotePort = server?.port;
-      })
-    );
-    this._addBarrier(
-      page,
-      response.securityDetails().then(details => {
-        if (details) networkEntry.response.securityDetails = details;
-      })
-    );
     this._addBarrier(
       page,
       response.allHeaders().then(resHeaders => {
@@ -197,6 +186,25 @@ export class NetworkManager {
     const networkEntry = this._findNetworkEntry(request);
     if (!networkEntry) return;
 
+    const page = request.frame().page();
+    const response = await request.response();
+    // response can be null if the request failed
+    if (response != null) {
+      this._addBarrier(
+        page,
+        response.serverAddr().then(server => {
+          networkEntry.response.remoteIPAddress = server?.ipAddress;
+          networkEntry.response.remotePort = server?.port;
+        })
+      );
+      this._addBarrier(
+        page,
+        response.securityDetails().then(details => {
+          if (details) networkEntry.response.securityDetails = details;
+        })
+      );
+    }
+
     networkEntry.loadEndTime = epochTimeInSeconds();
     const timing = request.timing();
     const { loadEndTime, requestSentTime } = networkEntry;
@@ -273,7 +281,6 @@ export class NetworkManager {
       total,
     };
 
-    const page = request.frame().page();
     // For aborted/failed requests sizes will not be present
     this._addBarrier(
       page,
@@ -301,6 +308,7 @@ export class NetworkManager {
     context.off('requestfinished', this._onRequestCompleted.bind(this));
     context.off('requestfailed', this._onRequestCompleted.bind(this));
     this._barrierPromises.clear();
+    log(`Plugins: stopped collecting network events`);
     return this.results;
   }
 }

src/plugins/tracing.ts

@@ -24,6 +24,7 @@
  */
 
 import { Driver, PluginOutput } from '../common_types';
+import { log } from '../core/logger';
 import { Filmstrips } from '../sdk/trace-metrics';
 import { TraceEvent, TraceProcessor } from '../sdk/trace-processor';
 
@@ -40,6 +41,7 @@ export class Tracing {
   constructor(private driver: Driver, private options: TraceOptions) {}
 
   async start() {
+    log(`Plugins: started collecting trace events`);
     const includedCategories = [
       // exclude all default categories
       '-*',
@@ -97,6 +99,7 @@ export class Tracing {
         ...TraceProcessor.computeTrace(traceEvents as Array<TraceEvent>),
       });
     }
+    log(`Plugins: stopped collecting trace events`);
     return output;
   }
 }