feat(connect): pw:server:channel and pw:socks debug logs (#23144)

Fixes #23081.
This commit is contained in:
Dmitry Gozman 2023-05-18 13:44:48 -07:00 committed by GitHub
parent ab7e794bf7
commit 422b65eeae
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 50 additions and 37 deletions

View File

@ -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;

View File

@ -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<void> {
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);
}

View File

@ -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<void>)[] = [];
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<void>, clientType: ClientType, ws: WebSocket, options: Options, preLaunched: PreLaunched, log: (m: string) => void, onClose: () => void) {
constructor(lock: Promise<void>, 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) {

View File

@ -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<string> {
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<string>((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');
}
}