fix(har): account for reused sockets (#33087)

Closes https://github.com/microsoft/playwright/issues/32960

If the socket is reused, the connect and DNS timings are set to -1,
because that timing doesn't apply to the current request. The time
between request start and the socket being free is counted as `blocked`.
This commit is contained in:
Simon Knott 2024-10-14 17:22:29 +02:00 committed by GitHub
parent 9fcf60464d
commit a8df750a48
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
2 changed files with 22 additions and 2 deletions

View File

@ -302,6 +302,7 @@ export abstract class APIRequestContext extends SdkObject {
const requestOptions = { ...options, agent };
const startAt = monotonicTime();
let reusedSocketAt: number | undefined;
let dnsLookupAt: number | undefined;
let tcpConnectionAt: number | undefined;
let tlsHandshakeAt: number | undefined;
@ -319,14 +320,15 @@ export abstract class APIRequestContext extends SdkObject {
const notifyRequestFinished = (body?: Buffer) => {
const endAt = monotonicTime();
// spec: http://www.softwareishard.com/blog/har-12-spec/#timings
const connectEnd = tlsHandshakeAt ?? tcpConnectionAt;
const timings: har.Timings = {
send: requestFinishAt! - startAt,
wait: responseAt - requestFinishAt!,
receive: endAt - responseAt,
dns: dnsLookupAt ? dnsLookupAt - startAt : -1,
connect: (tlsHandshakeAt ?? tcpConnectionAt!) - startAt, // "If [ssl] is defined then the time is also included in the connect field "
connect: connectEnd ? connectEnd - startAt : -1, // "If [ssl] is defined then the time is also included in the connect field "
ssl: tlsHandshakeAt ? tlsHandshakeAt - tcpConnectionAt! : -1,
blocked: -1,
blocked: reusedSocketAt ? reusedSocketAt - startAt : -1,
};
const requestFinishedEvent: APIRequestFinishedEvent = {
@ -489,6 +491,11 @@ export abstract class APIRequestContext extends SdkObject {
request.on('close', () => eventsHelper.removeEventListeners(listeners));
request.on('socket', socket => {
if (request.reusedSocket) {
reusedSocketAt = monotonicTime();
return;
}
// happy eyeballs don't emit lookup and connect events, so we use our custom ones
const happyEyeBallsTimings = timingForSocket(socket);
dnsLookupAt = happyEyeBallsTimings.dnsLookupAt;

View File

@ -877,6 +877,19 @@ it('should include timings when using socks proxy', async ({ contextFactory, ser
expect(log.entries[0].timings.connect).toBeGreaterThan(0);
});
it('should not have connect and dns timings when socket is reused', async ({ contextFactory, server }, testInfo) => {
const { page, getLog } = await pageWithHar(contextFactory, testInfo);
await page.request.get(server.EMPTY_PAGE);
await page.request.get(server.EMPTY_PAGE);
const log = await getLog();
expect(log.entries).toHaveLength(2);
const request2 = log.entries[1];
expect.soft(request2.timings.connect).toBe(-1);
expect.soft(request2.timings.dns).toBe(-1);
expect.soft(request2.timings.blocked).toBeGreaterThan(0);
});
it('should include redirects from API request', async ({ contextFactory, server }, testInfo) => {
server.setRedirect('/redirect-me', '/simple.json');
const { page, getLog } = await pageWithHar(contextFactory, testInfo);