diff --git a/packages/playwright-core/src/common/debugLogger.ts b/packages/playwright-core/src/common/debugLogger.ts index d0b3763268..ac0202fe3e 100644 --- a/packages/playwright-core/src/common/debugLogger.ts +++ b/packages/playwright-core/src/common/debugLogger.ts @@ -23,11 +23,13 @@ const debugLoggerColorMap = { 'install': 34, // green 'download': 34, // green 'browser': 0, // reset - 'proxy': 92, // purple + 'socks': 92, // purple 'error': 160, // red, 'channel:command': 33, // blue 'channel:response': 202, // orange 'channel:event': 207, // magenta + 'server': 45, // cyan + 'server:channel': 34, // green }; export type LogName = keyof typeof debugLoggerColorMap; diff --git a/packages/playwright-core/src/common/socksProxy.ts b/packages/playwright-core/src/common/socksProxy.ts index e0fe8bc73b..768d036cf3 100644 --- a/packages/playwright-core/src/common/socksProxy.ts +++ b/packages/playwright-core/src/common/socksProxy.ts @@ -436,7 +436,6 @@ export class SocksProxy extends EventEmitter implements SocksConnectionClient { this._server.listen(port, () => { const port = (this._server.address() as AddressInfo).port; this._port = port; - debugLogger.log('proxy', `Starting socks proxy server on port ${port}`); f(port); }); }); @@ -525,8 +524,10 @@ export class SocksProxyHandler extends EventEmitter { } async socketRequested({ uid, host, port }: SocksSocketRequestedPayload): Promise { + debugLogger.log('socks', `[${uid}] => request ${host}:${port}`); if (!this._patternMatcher(host, port)) { const payload: SocksSocketFailedPayload = { uid, errorCode: 'ERULESET' }; + debugLogger.log('socks', `[${uid}] <= pattern error ${payload.errorCode}`); this.emit(SocksProxyHandler.Events.SocksFailed, payload); return; } @@ -543,11 +544,13 @@ export class SocksProxyHandler extends EventEmitter { }); socket.on('error', error => { const payload: SocksSocketErrorPayload = { uid, error: error.message }; + debugLogger.log('socks', `[${uid}] <= network socket error ${payload.error}`); this.emit(SocksProxyHandler.Events.SocksError, payload); this._sockets.delete(uid); }); socket.on('end', () => { const payload: SocksSocketEndPayload = { uid }; + debugLogger.log('socks', `[${uid}] <= network socket closed`); this.emit(SocksProxyHandler.Events.SocksEnd, payload); this._sockets.delete(uid); }); @@ -555,9 +558,11 @@ export class SocksProxyHandler extends EventEmitter { const localPort = socket.localPort; this._sockets.set(uid, socket); const payload: SocksSocketConnectedPayload = { uid, host: localAddress, port: localPort }; + debugLogger.log('socks', `[${uid}] <= connected to network ${payload.host}:${payload.port}`); this.emit(SocksProxyHandler.Events.SocksConnected, payload); } catch (error) { const payload: SocksSocketFailedPayload = { uid, errorCode: error.code }; + debugLogger.log('socks', `[${uid}] <= connect error ${payload.errorCode}`); this.emit(SocksProxyHandler.Events.SocksFailed, payload); } } @@ -567,6 +572,7 @@ export class SocksProxyHandler extends EventEmitter { } socketClosed({ uid }: SocksSocketClosedPayload): void { + debugLogger.log('socks', `[${uid}] <= browser socket closed`); this._sockets.get(uid)?.destroy(); this._sockets.delete(uid); } diff --git a/packages/playwright-core/src/remote/playwrightConnection.ts b/packages/playwright-core/src/remote/playwrightConnection.ts index bcae6b4d69..73cc651f53 100644 --- a/packages/playwright-core/src/remote/playwrightConnection.ts +++ b/packages/playwright-core/src/remote/playwrightConnection.ts @@ -25,6 +25,8 @@ import type { LaunchOptions } from '../server/types'; import { AndroidDevice } from '../server/android/android'; import { DebugControllerDispatcher } from '../server/dispatchers/debugControllerDispatcher'; import { startProfiling, stopProfiling } from '../utils'; +import { monotonicTime } from '../utils'; +import { debugLogger } from '../common/debugLogger'; export type ClientType = 'controller' | 'playwright' | 'launch-browser' | 'reuse-browser' | 'pre-launched-browser-or-android'; @@ -46,14 +48,14 @@ export class PlaywrightConnection { private _onClose: () => void; private _dispatcherConnection: DispatcherConnection; private _cleanups: (() => Promise)[] = []; - private _debugLog: (m: string) => void; + private _id: string; private _disconnected = false; private _preLaunched: PreLaunched; private _options: Options; private _root: DispatcherScope; private _profileName: string; - constructor(lock: Promise, clientType: ClientType, ws: WebSocket, options: Options, preLaunched: PreLaunched, log: (m: string) => void, onClose: () => void) { + constructor(lock: Promise, clientType: ClientType, ws: WebSocket, options: Options, preLaunched: PreLaunched, id: string, onClose: () => void) { this._ws = ws; this._preLaunched = preLaunched; this._options = options; @@ -63,18 +65,25 @@ export class PlaywrightConnection { if (clientType === 'pre-launched-browser-or-android') assert(preLaunched.browser || preLaunched.androidDevice); this._onClose = onClose; - this._debugLog = log; + this._id = id; this._profileName = `${new Date().toISOString()}-${clientType}`; this._dispatcherConnection = new DispatcherConnection(); this._dispatcherConnection.onmessage = async message => { await lock; - if (ws.readyState !== ws.CLOSING) - ws.send(JSON.stringify(message)); + if (ws.readyState !== ws.CLOSING) { + const messageString = JSON.stringify(message); + if (debugLogger.isEnabled('server:channel')) + debugLogger.log('server:channel', `[${this._id}] ${monotonicTime() * 1000} SEND ► ${messageString}`); + ws.send(messageString); + } }; ws.on('message', async (message: string) => { await lock; - this._dispatcherConnection.dispatch(JSON.parse(Buffer.from(message).toString())); + const messageString = Buffer.from(message).toString(); + if (debugLogger.isEnabled('server:channel')) + debugLogger.log('server:channel', `[${this._id}] ${monotonicTime() * 1000} ◀ RECV ${messageString}`); + this._dispatcherConnection.dispatch(JSON.parse(messageString)); }); ws.on('close', () => this._onDisconnect()); @@ -100,7 +109,7 @@ export class PlaywrightConnection { } private async _initPlaywrightConnectMode(scope: RootDispatcher) { - this._debugLog(`engaged playwright.connect mode`); + debugLogger.log('server', `[${this._id}] engaged playwright.connect mode`); const playwright = createPlaywright('javascript'); // Close all launched browsers on disconnect. this._cleanups.push(async () => { @@ -112,7 +121,7 @@ export class PlaywrightConnection { } private async _initLaunchBrowserMode(scope: RootDispatcher) { - this._debugLog(`engaged launch mode for "${this._options.browserName}"`); + debugLogger.log('server', `[${this._id}] engaged launch mode for "${this._options.browserName}"`); const playwright = createPlaywright('javascript'); const ownedSocksProxy = await this._createOwnedSocksProxy(playwright); @@ -131,7 +140,7 @@ export class PlaywrightConnection { } private async _initPreLaunchedBrowserMode(scope: RootDispatcher) { - this._debugLog(`engaged pre-launched (browser) mode`); + debugLogger.log('server', `[${this._id}] engaged pre-launched (browser) mode`); const playwright = this._preLaunched.playwright!; // Note: connected client owns the socks proxy and configures the pattern. @@ -154,7 +163,7 @@ export class PlaywrightConnection { } private async _initPreLaunchedAndroidMode(scope: RootDispatcher) { - this._debugLog(`engaged pre-launched (Android) mode`); + debugLogger.log('server', `[${this._id}] engaged pre-launched (Android) mode`); const playwright = this._preLaunched.playwright!; const androidDevice = this._preLaunched.androidDevice!; androidDevice.on(AndroidDevice.Events.Close, () => { @@ -167,7 +176,7 @@ export class PlaywrightConnection { } private _initDebugControllerMode(): DebugControllerDispatcher { - this._debugLog(`engaged reuse controller mode`); + debugLogger.log('server', `[${this._id}] engaged reuse controller mode`); const playwright = this._preLaunched.playwright!; // Always create new instance based on the reused Playwright instance. return new DebugControllerDispatcher(this._dispatcherConnection, playwright.debugController); @@ -177,7 +186,7 @@ export class PlaywrightConnection { // Note: reuse browser mode does not support socks proxy, because // clients come and go, while the browser stays the same. - this._debugLog(`engaged reuse browsers mode for ${this._options.browserName}`); + debugLogger.log('server', `[${this._id}] engaged reuse browsers mode for ${this._options.browserName}`); const playwright = this._preLaunched.playwright!; const requestedOptions = launchOptionsHash(this._options.launchOptions); @@ -232,27 +241,27 @@ export class PlaywrightConnection { const socksProxy = new SocksProxy(); socksProxy.setPattern(this._options.socksProxyPattern); playwright.options.socksProxyPort = await socksProxy.listen(0); - this._debugLog(`started socks proxy on port ${playwright.options.socksProxyPort}`); + debugLogger.log('server', `[${this._id}] started socks proxy on port ${playwright.options.socksProxyPort}`); this._cleanups.push(() => socksProxy.close()); return socksProxy; } private async _onDisconnect(error?: Error) { this._disconnected = true; - this._debugLog(`disconnected. error: ${error}`); + debugLogger.log('server', `[${this._id}] disconnected. error: ${error}`); this._root._dispose(); - this._debugLog(`starting cleanup`); + debugLogger.log('server', `[${this._id}] starting cleanup`); for (const cleanup of this._cleanups) await cleanup().catch(() => {}); await stopProfiling(this._profileName); this._onClose(); - this._debugLog(`finished cleanup`); + debugLogger.log('server', `[${this._id}] finished cleanup`); } async close(reason?: { code: number, reason: string }) { if (this._disconnected) return; - this._debugLog(`force closing connection: ${reason?.reason || ''} (${reason?.code || 0})`); + debugLogger.log('server', `[${this._id}] force closing connection: ${reason?.reason || ''} (${reason?.code || 0})`); try { this._ws.close(reason?.code, reason?.reason); } catch (e) { diff --git a/packages/playwright-core/src/remote/playwrightServer.ts b/packages/playwright-core/src/remote/playwrightServer.ts index 8fb32a0fac..e359494883 100644 --- a/packages/playwright-core/src/remote/playwrightServer.ts +++ b/packages/playwright-core/src/remote/playwrightServer.ts @@ -14,7 +14,7 @@ * limitations under the License. */ -import { debug, wsServer } from '../utilsBundle'; +import { wsServer } from '../utilsBundle'; import type { WebSocketServer } from '../utilsBundle'; import http from 'http'; import type { Browser } from '../server/browser'; @@ -26,17 +26,11 @@ import type { LaunchOptions } from '../server/types'; import { ManualPromise } from '../utils/manualPromise'; import type { AndroidDevice } from '../server/android/android'; import { type SocksProxy } from '../common/socksProxy'; - -const debugLog = debug('pw:server'); +import { debugLogger } from '../common/debugLogger'; let lastConnectionId = 0; const kConnectionSymbol = Symbol('kConnection'); -function newLogger() { - const id = ++lastConnectionId; - return (message: string) => debugLog(`[id=${id}] ${message}`); -} - type ServerOptions = { path: string; maxConnections: number; @@ -59,6 +53,8 @@ export class PlaywrightServer { } async listen(port: number = 0): Promise { + debugLogger.log('server', `Server started at ${new Date()}`); + const server = http.createServer((request: http.IncomingMessage, response: http.ServerResponse) => { if (request.method === 'GET' && request.url === '/json') { response.setHeader('Content-Type', 'application/json'); @@ -69,7 +65,7 @@ export class PlaywrightServer { } response.end('Running'); }); - server.on('error', error => debugLog(error)); + server.on('error', error => debugLogger.log('server', String(error))); const wsEndpoint = await new Promise((resolve, reject) => { server.listen(port, () => { @@ -83,7 +79,7 @@ export class PlaywrightServer { }).on('error', reject); }); - debugLog('Listening at ' + wsEndpoint); + debugLogger.log('server', 'Listening at ' + wsEndpoint); this._wsServer = new wsServer({ server, path: this._options.path }); const browserSemaphore = new Semaphore(this._options.maxConnections); const controllerSemaphore = new Semaphore(1); @@ -107,8 +103,8 @@ export class PlaywrightServer { } catch (e) { } - const log = newLogger(); - log(`serving connection: ${request.url}`); + const id = String(++lastConnectionId); + debugLogger.log('server', `[${id}] serving connection: ${request.url}`); const isDebugControllerClient = !!request.headers['x-playwright-debug-controller']; const shouldReuseBrowser = !!request.headers['x-playwright-reuse-context']; @@ -145,7 +141,7 @@ export class PlaywrightServer { androidDevice: this._options.preLaunchedAndroidDevice, socksProxy: this._options.preLaunchedSocksProxy, }, - log, () => semaphore.release()); + id, () => semaphore.release()); (ws as any)[kConnectionSymbol] = connection; }); @@ -156,7 +152,7 @@ export class PlaywrightServer { const server = this._wsServer; if (!server) return; - debugLog('closing websocket server'); + debugLogger.log('server', 'closing websocket server'); const waitForClose = new Promise(f => server.close(f)); // First disconnect all remaining clients. await Promise.all(Array.from(server.clients).map(async ws => { @@ -169,15 +165,15 @@ export class PlaywrightServer { } })); await waitForClose; - debugLog('closing http server'); + debugLogger.log('server', 'closing http server'); await new Promise(f => server.options.server!.close(f)); this._wsServer = undefined; - debugLog('closed server'); + debugLogger.log('server', 'closed server'); - debugLog('closing browsers'); + debugLogger.log('server', 'closing browsers'); if (this._preLaunchedPlaywright) await Promise.all(this._preLaunchedPlaywright.allBrowsers().map(browser => browser.close())); - debugLog('closed browsers'); + debugLogger.log('server', 'closed browsers'); } }