From 82cab094e89edf92040c62aa10ab91832e349da3 Mon Sep 17 00:00:00 2001 From: Dmitry Gozman Date: Mon, 18 May 2020 19:00:38 -0700 Subject: [PATCH] feat(logging): add logging to websocket transport (#2289) --- src/server/chromium.ts | 5 +++-- src/server/electron.ts | 2 +- src/server/firefox.ts | 13 ++++++++----- src/server/webkit.ts | 5 +++-- src/transport.ts | 20 +++++++++++++++----- test/fixtures.spec.js | 1 + test/test.config.js | 13 ++++++++++--- test/test.js | 31 +++++-------------------------- test/utils.js | 39 +++++++++++++++++++++++++++++++++------ 9 files changed, 79 insertions(+), 50 deletions(-) diff --git a/src/server/chromium.ts b/src/server/chromium.ts index 6c397aa17d..b0cbc9ef68 100644 --- a/src/server/chromium.ts +++ b/src/server/chromium.ts @@ -155,11 +155,12 @@ export class Chromium extends AbstractBrowserType { } async connect(options: ConnectOptions): Promise { + const logger = new RootLogger(options.logger); return await WebSocketTransport.connect(options.wsEndpoint, async transport => { if ((options as any).__testHookBeforeCreateBrowser) await (options as any).__testHookBeforeCreateBrowser(); - return CRBrowser.connect(transport, { slowMo: options.slowMo, logger: new RootLogger(options.logger), downloadsPath: '' }); - }); + return CRBrowser.connect(transport, { slowMo: options.slowMo, logger, downloadsPath: '' }); + }, logger); } private _defaultArgs(options: BrowserArgOptions = {}, launchType: LaunchType, userDataDir: string): string[] { diff --git a/src/server/electron.ts b/src/server/electron.ts index 69adbaddda..2695624a3c 100644 --- a/src/server/electron.ts +++ b/src/server/electron.ts @@ -202,7 +202,7 @@ export class Electron { const chromeMatch = await waitForLine(launchedProcess, launchedProcess.stderr, /^DevTools listening on (ws:\/\/.*)$/, helper.timeUntilDeadline(deadline), timeoutError); const chromeTransport = await WebSocketTransport.connect(chromeMatch[1], transport => { return transport; - }); + }, logger); const browserServer = new BrowserServer(launchedProcess, gracefullyClose, null); const browser = await CRBrowser.connect(chromeTransport, { headful: true, logger, persistent: true, viewport: null, ownedServer: browserServer, downloadsPath: '' }); app = new ElectronApplication(logger, browser, nodeConnection); diff --git a/src/server/firefox.ts b/src/server/firefox.ts index cdb80061a8..d5a56e06f9 100644 --- a/src/server/firefox.ts +++ b/src/server/firefox.ts @@ -58,7 +58,7 @@ export class Firefox extends AbstractBrowserType { headful: !processBrowserArgOptions(options).headless, ownedServer: browserServer, }); - }); + }, logger); return browser; }); } @@ -83,7 +83,7 @@ export class Firefox extends AbstractBrowserType { ownedServer: browserServer, headful: !processBrowserArgOptions(options).headless, }); - }); + }, logger); const context = browser._defaultContext!; if (!options.ignoreDefaultArgs || Array.isArray(options.ignoreDefaultArgs)) await context._loadDefaultContext(); @@ -159,18 +159,21 @@ export class Firefox extends AbstractBrowserType { const match = await waitForLine(launchedProcess, launchedProcess.stdout, /^Juggler listening on (ws:\/\/.*)$/, timeout, timeoutError); const innerEndpoint = match[1]; - const webSocketWrapper = launchType === 'server' ? (await WebSocketTransport.connect(innerEndpoint, t => wrapTransportWithWebSocket(t, logger, port))) : new WebSocketWrapper(innerEndpoint, []); + const webSocketWrapper = launchType === 'server' ? + (await WebSocketTransport.connect(innerEndpoint, t => wrapTransportWithWebSocket(t, logger, port), logger)) : + new WebSocketWrapper(innerEndpoint, []); browserWSEndpoint = webSocketWrapper.wsEndpoint; browserServer = new BrowserServer(launchedProcess, gracefullyClose, webSocketWrapper); return { browserServer, downloadsPath, logger }; } async connect(options: ConnectOptions): Promise { + const logger = new RootLogger(options.logger); return await WebSocketTransport.connect(options.wsEndpoint, async transport => { if ((options as any).__testHookBeforeCreateBrowser) await (options as any).__testHookBeforeCreateBrowser(); - return FFBrowser.connect(transport, { slowMo: options.slowMo, logger: new RootLogger(options.logger), downloadsPath: '' }); - }); + return FFBrowser.connect(transport, { slowMo: options.slowMo, logger, downloadsPath: '' }); + }, logger); } private _defaultArgs(options: BrowserArgOptions = {}, launchType: LaunchType, userDataDir: string, port: number): string[] { diff --git a/src/server/webkit.ts b/src/server/webkit.ts index e78d3ff37b..60ff0d76ae 100644 --- a/src/server/webkit.ts +++ b/src/server/webkit.ts @@ -150,11 +150,12 @@ export class WebKit extends AbstractBrowserType { } async connect(options: ConnectOptions): Promise { + const logger = new RootLogger(options.logger); return await WebSocketTransport.connect(options.wsEndpoint, async transport => { if ((options as any).__testHookBeforeCreateBrowser) await (options as any).__testHookBeforeCreateBrowser(); - return WKBrowser.connect(transport, { slowMo: options.slowMo, logger: new RootLogger(options.logger), downloadsPath: '' }); - }); + return WKBrowser.connect(transport, { slowMo: options.slowMo, logger, downloadsPath: '' }); + }, logger); } _defaultArgs(options: BrowserArgOptions = {}, launchType: LaunchType, userDataDir: string, port: number): string[] { diff --git a/src/transport.ts b/src/transport.ts index 0f901fa2fd..810eab1efa 100644 --- a/src/transport.ts +++ b/src/transport.ts @@ -17,7 +17,7 @@ import * as WebSocket from 'ws'; import { helper } from './helper'; -import { Log } from './logger'; +import { Log, InnerLogger } from './logger'; export type ProtocolRequest = { id: number; @@ -120,32 +120,40 @@ export class DeferWriteTransport implements ConnectionTransport { export class WebSocketTransport implements ConnectionTransport { _ws: WebSocket; + _logger?: InnerLogger; onmessage?: (message: ProtocolResponse) => void; onclose?: () => void; // 'onmessage' handler must be installed synchronously when 'onopen' callback is invoked to // avoid missing incoming messages. - static connect(url: string, onopen: (transport: ConnectionTransport) => Promise | T): Promise { - const transport = new WebSocketTransport(url); + static connect(url: string, onopen: (transport: ConnectionTransport) => Promise | T, logger?: InnerLogger): Promise { + logger && logger._log({ name: 'browser' }, ` ${url}`); + const transport = new WebSocketTransport(url, logger); return new Promise((fulfill, reject) => { transport._ws.addEventListener('open', async () => { + logger && logger._log({ name: 'browser' }, ` ${url}`); try { fulfill(await onopen(transport)); } catch (e) { + logger && logger._log({ name: 'browser' }, ` ${url}`); try { transport._ws.close(); } catch (ignored) {} reject(e); } }); - transport._ws.addEventListener('error', event => reject(new Error('WebSocket error: ' + event.message))); + transport._ws.addEventListener('error', event => { + logger && logger._log({ name: 'browser' }, ` ${url} ${event.message}`); + reject(new Error('WebSocket error: ' + event.message)); + }); }); } - constructor(url: string) { + constructor(url: string, logger: InnerLogger | undefined) { this._ws = new WebSocket(url, [], { perMessageDeflate: false, maxPayload: 256 * 1024 * 1024, // 256Mb }); + this._logger = logger; // The 'ws' module in node sometimes sends us multiple messages in a single task. // In Web, all IO callbacks (e.g. WebSocket callbacks) // are dispatched into separate tasks, so there's no need @@ -160,6 +168,7 @@ export class WebSocketTransport implements ConnectionTransport { }); this._ws.addEventListener('close', event => { + this._logger && this._logger._log({ name: 'browser' }, ` ${url}`); if (this.onclose) this.onclose.call(null); }); @@ -172,6 +181,7 @@ export class WebSocketTransport implements ConnectionTransport { } close() { + this._logger && this._logger._log({ name: 'browser' }, ` ${this._ws.url}`); this._ws.close(); } } diff --git a/test/fixtures.spec.js b/test/fixtures.spec.js index 86c0fa5c43..c18e5a233d 100644 --- a/test/fixtures.spec.js +++ b/test/fixtures.spec.js @@ -25,6 +25,7 @@ async function testSignal(state, action, exitOnClose) { handleSIGTERM: true, handleSIGHUP: true, executablePath: state.browserType.executablePath(), + logger: undefined, }); const res = spawn('node', [path.join(__dirname, 'fixtures', 'closeme.js'), path.join(state.playwrightPath, 'index-for-dev'), state.browserType.name(), JSON.stringify(options), exitOnClose ? 'true' : '']); let wsEndPointCallback; diff --git a/test/test.config.js b/test/test.config.js index 7b6a12a7df..c9c5a69d6a 100644 --- a/test/test.config.js +++ b/test/test.config.js @@ -18,6 +18,7 @@ const fs = require('fs'); const path = require('path'); const rm = require('rimraf').sync; +const utils = require('./utils'); const {TestServer} = require('../utils/testserver/'); const {Environment} = require('../utils/testrunner/Test'); @@ -44,10 +45,12 @@ serverEnvironment.beforeAll(async state => { state.httpsServer.CROSS_PROCESS_PREFIX = `https://127.0.0.1:${httpsPort}`; state.httpsServer.EMPTY_PAGE = `https://localhost:${httpsPort}/empty.html`; + state._extraLogger = utils.createTestLogger(valueFromEnv('DEBUGP', false), null, 'extra'); state.defaultBrowserOptions = { handleSIGINT: false, slowMo: valueFromEnv('SLOW_MO', 0), headless: !!valueFromEnv('HEADLESS', true), + logger: state._extraLogger, }; state.playwrightPath = playwrightPath; }); @@ -57,9 +60,13 @@ serverEnvironment.afterAll(async({server, httpsServer}) => { httpsServer.stop(), ]); }); -serverEnvironment.beforeEach(async({server, httpsServer}) => { - server.reset(); - httpsServer.reset(); +serverEnvironment.beforeEach(async(state, testRun) => { + state.server.reset(); + state.httpsServer.reset(); + state._extraLogger.setTestRun(testRun); +}); +serverEnvironment.afterEach(async(state) => { + state._extraLogger.setTestRun(null); }); const customEnvironment = new Environment('Golden+CheckContexts'); diff --git a/test/test.js b/test/test.js index b09bebde7d..3020069647 100644 --- a/test/test.js +++ b/test/test.js @@ -17,6 +17,7 @@ const fs = require('fs'); const path = require('path'); +const utils = require('./utils'); const TestRunner = require('../utils/testrunner/'); const {Environment} = require('../utils/testrunner/Test'); @@ -120,17 +121,8 @@ function collect(browserNames) { const browserEnvironment = new Environment(browserName); browserEnvironment.beforeAll(async state => { - state._logger = null; - state.browser = await state.browserType.launch({...launchOptions, logger: { - isEnabled: (name, severity) => { - return name === 'browser' || - (name === 'protocol' && config.dumpProtocolOnFailure); - }, - log: (name, severity, message, args) => { - if (state._logger) - state._logger(name, severity, message); - } - }}); + state._logger = utils.createTestLogger(config.dumpProtocolOnFailure); + state.browser = await state.browserType.launch({...launchOptions, logger: state._logger}); }); browserEnvironment.afterAll(async state => { await state.browser.close(); @@ -138,23 +130,10 @@ function collect(browserNames) { delete state._logger; }); browserEnvironment.beforeEach(async(state, testRun) => { - state._logger = (name, severity, message) => { - if (name === 'browser') { - if (severity === 'warning') - testRun.log(`\x1b[31m[browser]\x1b[0m ${message}`) - else - testRun.log(`\x1b[33m[browser]\x1b[0m ${message}`) - } else if (name === 'protocol' && config.dumpProtocolOnFailure) { - testRun.log(`\x1b[32m[protocol]\x1b[0m ${message}`) - } - } + state._logger.setTestRun(testRun); }); browserEnvironment.afterEach(async (state, testRun) => { - state._logger = null; - if (config.dumpProtocolOnFailure) { - if (testRun.ok()) - testRun.output().splice(0); - } + state._logger.setTestRun(null); }); const pageEnvironment = new Environment('Page'); diff --git a/test/utils.js b/test/utils.js index 961af67397..5d206d1df4 100644 --- a/test/utils.js +++ b/test/utils.js @@ -191,10 +191,37 @@ const utils = module.exports = { // To support isplaywrightready. platform = p; }, -}; -function valueFromEnv(name, defaultValue) { - if (!(name in process.env)) - return defaultValue; - return JSON.parse(process.env[name]); -} + createTestLogger(dumpProtocolOnFailure = true, testRun = null, prefix = '') { + const colors = [31, 32, 33, 34, 35, 36, 37]; + let colorIndex = 0; + for (let i = 0; i < prefix.length; i++) + colorIndex += prefix.charCodeAt(i); + const color = colors[colorIndex % colors.length]; + prefix = prefix ? `\x1b[${color}m[${prefix}]\x1b[0m ` : ''; + + const logger = { + isEnabled: (name, severity) => { + return name === 'browser' || (name === 'protocol' && dumpProtocolOnFailure); + }, + log: (name, severity, message, args) => { + if (!testRun) + return; + if (name === 'browser') { + if (severity === 'warning') + testRun.log(`${prefix}\x1b[31m[browser]\x1b[0m ${message}`) + else + testRun.log(`${prefix}\x1b[33m[browser]\x1b[0m ${message}`) + } else if (name === 'protocol' && dumpProtocolOnFailure) { + testRun.log(`${prefix}\x1b[32m[protocol]\x1b[0m ${message}`) + } + }, + setTestRun(tr) { + if (testRun && testRun.ok()) + testRun.output().splice(0); + testRun = tr; + }, + }; + return logger; + }, +};