From 4ef4cfbb41450805480defd2aa6abf9b299ea920 Mon Sep 17 00:00:00 2001 From: Brendan Kenny Date: Wed, 22 Feb 2023 16:14:41 -0600 Subject: [PATCH] core: don't use failed network requests as potential initiators (#14819) --- core/lib/network-recorder.js | 7 +- core/test/lib/network-recorder-test.js | 601 +++++++----------- .../network-records-to-devtools-log-test.js | 1 + core/test/network-records-to-devtools-log.js | 3 +- 4 files changed, 250 insertions(+), 362 deletions(-) diff --git a/core/lib/network-recorder.js b/core/lib/network-recorder.js index 2d3797bd10..d0e1b7c76c 100644 --- a/core/lib/network-recorder.js +++ b/core/lib/network-recorder.js @@ -247,8 +247,11 @@ class NetworkRecorder extends RequestEventEmitter { const initiatorURL = PageDependencyGraph.getNetworkInitiators(record)[0]; let candidates = recordsByURL.get(initiatorURL) || []; - // The initiator must come before the initiated request. - candidates = candidates.filter(c => c.responseHeadersEndTime <= record.networkRequestTime); + // The (valid) initiator must come before the initiated request. + candidates = candidates.filter(c => { + return c.responseHeadersEndTime <= record.networkRequestTime && + c.finished && !c.failed; + }); if (candidates.length > 1) { // Disambiguate based on prefetch. Prefetch requests have type 'Other' and cannot // initiate requests, so we drop them here. diff --git a/core/test/lib/network-recorder-test.js b/core/test/lib/network-recorder-test.js index 16f3b28ccc..ad323c8988 100644 --- a/core/test/lib/network-recorder-test.js +++ b/core/test/lib/network-recorder-test.js @@ -229,69 +229,35 @@ describe('network recorder', function() { it('Not set initiators when timings are invalid', () => { // Note that the followings are contrived for testing purposes and are - // unlikely to occur in practice. - const logs = [ + // unlikely to occur in practice. In particular, the initiator's timestamp + // is after the initiated's timestamp. + const devtoolsLog = networkRecordsToDevtoolsLog([ { // initiator - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '1', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 107988.912007, - 'wallTime': 1466620735.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'Other', - }, - }, - { // initiator response - 'method': 'Network.responseReceived', - 'params': { - 'requestId': '1', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'response': { - 'url': 'https://www.example.com/initiator', - 'status': '200', - 'headers': {}, - }, - 'timestamp': 108088.912007, - 'wallTime': 1466620835.21187, - }, + requestId: '1', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + rendererStartTime: 107988912.007, + responseHeadersEndTime: 108088912.007, + initiator: {type: 'other'}, + resourceType: 'Other', + statusCode: 200, }, { // initiated - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '2', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiated', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 106988.912007, - 'wallTime': 1466620635.21187, - 'initiator': { - 'type': 'script', - 'url': 'https://www.example.com/initiator', - }, - 'type': 'Other', + requestId: '2', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiated', + rendererStartTime: 106988912.007, + initiator: { + type: 'script', + url: 'https://www.example.com/initiator', }, + resourceType: 'Other', }, - ]; - const records = NetworkRecorder.recordsFromLogs(logs); + ]); + + const records = NetworkRecorder.recordsFromLogs(devtoolsLog); expect(records).toHaveLength(2); const [initiator, initiated] = records; @@ -301,54 +267,33 @@ describe('network recorder', function() { it(`should allow 'Other' initiators when unambiguous`, () => { // Note that the followings are contrived for testing purposes and are - // unlikely to occur in practice. In particular, the initiator's timestamp - // is after the initiated's timestamp. - const logs = [ + // unlikely to occur in practice. + const devtoolsLog = networkRecordsToDevtoolsLog([ { // initiator - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '1', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 107988.912007, - 'wallTime': 1466620735.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'Other', - }, + requestId: '1', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + priority: 'VeryHigh', + rendererStartTime: 107988912.007, + initiator: {type: 'other'}, + resourceType: 'Other', }, { // initiated - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '2', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiated', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 108088.912007, - 'wallTime': 1466620835.21187, - 'initiator': { - 'type': 'script', - 'url': 'https://www.example.com/initiator', - }, - 'type': 'Other', + requestId: '2', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiated', + rendererStartTime: 108088912.007, + initiator: { + type: 'script', + url: 'https://www.example.com/initiator', }, + resourceType: 'Other', }, - ]; - const records = NetworkRecorder.recordsFromLogs(logs); + ]); + + const records = NetworkRecorder.recordsFromLogs(devtoolsLog); expect(records).toHaveLength(2); const [initiator, initiated] = records; @@ -358,75 +303,42 @@ describe('network recorder', function() { it('should give higher precedence to same-frame initiators', () => { // Note that the followings are contrived for testing purposes and are - // unlikely to occur in practice. In particular, the initiator's timestamp - // is after the initiated's timestamp. - const logs = [ + // unlikely to occur in practice. + const devtoolsLog = networkRecordsToDevtoolsLog([ { // initiator (frame 1) - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '1', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 107988.912007, - 'wallTime': 1466620735.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'Script', - }, + requestId: '1', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + priority: 'VeryHigh', + rendererStartTime: 107988912.007, + initiator: {type: 'other'}, + resourceType: 'Script', }, { // initiator (frame 2) - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '2', - 'frameId': '2', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 108088.912007, - 'wallTime': 1466620835.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'Script', - }, + requestId: '2', + frameId: '2', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + rendererStartTime: 108088912.007, + initiator: {type: 'other'}, + resourceType: 'Script', }, { // initiated (frame 2) - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '3', - 'frameId': '2', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiated', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 108188.912007, - 'wallTime': 1466620935.21187, - 'initiator': { - 'type': 'script', - 'url': 'https://www.example.com/initiator', - }, - 'type': 'Script', + requestId: '3', + frameId: '2', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiated', + rendererStartTime: 108188912.007, + initiator: { + type: 'script', + url: 'https://www.example.com/initiator', }, + resourceType: 'Script', }, - ]; - const records = NetworkRecorder.recordsFromLogs(logs); + ]); + + const records = NetworkRecorder.recordsFromLogs(devtoolsLog); expect(records).toHaveLength(3); const [initiator1, initiator2, initiated] = records; @@ -438,73 +350,42 @@ describe('network recorder', function() { }); it('should give higher precedence to document initiators', () => { - const logs = [ + const devtoolsLog = networkRecordsToDevtoolsLog([ { // initiator (Document) - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '1', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 107988.912007, - 'wallTime': 1466620735.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'Document', - }, + requestId: '1', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + priority: 'VeryHigh', + rendererStartTime: 107988912.007, + initiator: {type: 'other'}, + resourceType: 'Document', }, { // initiator (XHR) - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '2', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 108088.912007, - 'wallTime': 1466620835.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'XHR', - }, + requestId: '2', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + priority: 'VeryHigh', + rendererStartTime: 108088912.007, + initiator: {type: 'other'}, + resourceType: 'XHR', }, { // initiated - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '3', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiated', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 108188.912007, - 'wallTime': 1466620935.21187, - 'initiator': { - 'type': 'parser', - 'url': 'https://www.example.com/initiator', - }, - 'type': 'Script', + requestId: '3', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiated', + rendererStartTime: 108188912.007, + initiator: { + type: 'parser', + url: 'https://www.example.com/initiator', }, + resourceType: 'Script', }, - ]; - const records = NetworkRecorder.recordsFromLogs(logs); + ]); + + const records = NetworkRecorder.recordsFromLogs(devtoolsLog); expect(records).toHaveLength(3); const [initiator1, initiator2, initiated] = records; @@ -517,89 +398,42 @@ describe('network recorder', function() { // Note that the followings are contrived for testing purposes and are // unlikely to occur in practice. In particular, the initiator's timestamp // is after the initiated's timestamp. - const logs = [ + const devtoolsLog = networkRecordsToDevtoolsLog([ { // initiator (frame 1) - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '1', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 107988.912007, - 'wallTime': 1466620735.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'Script', - }, + requestId: '1', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + priority: 'VeryHigh', + rendererStartTime: 107988912.007, + initiator: {type: 'other'}, + resourceType: 'Script', }, { // initiator (frame 2) - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '2', - 'frameId': '2', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 108388.912007, - 'wallTime': 1466621035.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'Script', - }, - }, - { - 'method': 'Network.responseReceived', - 'params': { - 'requestId': '2', - 'frameId': '2', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'response': { - 'url': 'https://www.example.com/initiator', - 'status': '200', - 'headers': {}, - }, - 'timestamp': 108488.912007, - 'wallTime': 1466621135.21187, - }, + requestId: '2', + frameId: '2', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + rendererStartTime: 108388912.007, + responseHeadersEndTime: 108488912.007, + initiator: {type: 'other'}, + resourceType: 'Script', }, { // initiated (frame 2) - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '3', - 'frameId': '2', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiated', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 108188.912007, - 'wallTime': 1466620935.21187, - 'initiator': { - 'type': 'script', - 'url': 'https://www.example.com/initiator', - }, - 'type': 'Script', + requestId: '3', + frameId: '2', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiated', + rendererStartTime: 108188912.007, + initiator: { + type: 'script', + url: 'https://www.example.com/initiator', }, + resourceType: 'Script', }, - ]; - const records = NetworkRecorder.recordsFromLogs(logs); + ]); + + const records = NetworkRecorder.recordsFromLogs(devtoolsLog); expect(records).toHaveLength(3); const [initiator1, initiator2, initiated] = records; @@ -695,74 +529,123 @@ describe('network recorder', function() { expect(imageRequest.initiatorRequest).toBe(preloadRequest); }); + it('should discard failed initiators', () => { + const url = 'https://redirecty.test/'; + const frameId = 'MAIN_FRAME'; + const redirectInitiator = { + type: 'script', + stack: { + callFrames: [{ + functionName: 'util.reload', + url, + scriptId: '1', + lineNumber: 4, + columnNumber: 1000, + }], + }, + }; + + // A page uses JS to refresh itself, with a spurious failed request in between. + const devtoolsLog = networkRecordsToDevtoolsLog([ + { + url, + frameId, + requestId: 'ROOT_DOC', + resourceType: 'Document', + initiator: {type: 'other'}, + protocol: 'h2', + statusCode: 200, + failed: false, + finished: true, + rendererStartTime: 10, + networkRequestTime: 15, + responseHeadersEndTime: 200, + networkEndTime: 300, + transferSize: 11_000, + resourceSize: 50_000, + }, + { + url, + frameId, + requestId: 'FAILED_DOC', + resourceType: 'Document', + initiator: redirectInitiator, + protocol: '', + statusCode: -1, + failed: true, + finished: true, + localizedFailDescription: 'net::ERR_ABORTED', + rendererStartTime: 500, + networkRequestTime: 500, + responseHeadersEndTime: -1, + networkEndTime: 501, + transferSize: 0, + resourceSize: 0, + }, + { + url, + frameId, + requestId: 'REFRESH_DOC', + resourceType: 'Document', + initiator: redirectInitiator, + protocol: 'h3', + statusCode: 200, + failed: false, + finished: true, + rendererStartTime: 503, + networkRequestTime: 504, + responseHeadersEndTime: 700, + networkEndTime: 800, + transferSize: 10_000, + resourceSize: 51_000, + }, + ]); + + const records = NetworkRecorder.recordsFromLogs(devtoolsLog); + expect(records).toHaveLength(3); + + const [rootDoc, failedDoc, refreshDoc] = records; + expect(rootDoc.initiatorRequest).toBe(undefined); + expect(failedDoc.initiatorRequest).toBe(rootDoc); + expect(refreshDoc.initiatorRequest).toBe(rootDoc); + }); + it('should not set initiator when ambiguous', () => { - const logs = [ + const devtoolsLog = networkRecordsToDevtoolsLog([ { // initiator A - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '1', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 107988.912007, - 'wallTime': 1466620735.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'Script', - }, + requestId: '1', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + priority: 'VeryHigh', + rendererStartTime: 107988912.007, + initiator: {type: 'other'}, + resourceType: 'Script', }, { // initiator B - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '2', - 'frameId': '1', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiator', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 108388.912007, - 'wallTime': 1466621035.21187, - 'initiator': { - 'type': 'other', - }, - 'type': 'Script', - }, + requestId: '2', + frameId: '1', + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiator', + rendererStartTime: 108188912.007, + initiator: {type: 'other'}, + resourceType: 'Script', }, { // initiated - 'method': 'Network.requestWillBeSent', - 'params': { - 'requestId': '3', - 'frameId': '2', - 'loaderId': '1', - 'documentURL': 'https://www.example.com/home', - 'request': { - 'url': 'https://www.example.com/initiated', - 'method': 'GET', - 'mixedContentType': 'none', - 'initialPriority': 'VeryHigh', - }, - 'timestamp': 108188.912007, - 'wallTime': 1466620935.21187, - 'initiator': { - 'type': 'script', - 'url': 'https://www.example.com/initiator', - }, - 'type': 'Script', + requestId: '3', + frameId: '2', // Intentionally frame 2. + documentURL: 'https://www.example.com/home', + url: 'https://www.example.com/initiated', + rendererStartTime: 108388912.007, + initiator: { + type: 'script', + url: 'https://www.example.com/initiator', }, + resourceType: 'Script', }, - ]; - const records = NetworkRecorder.recordsFromLogs(logs); + ]); + + const records = NetworkRecorder.recordsFromLogs(devtoolsLog); expect(records).toHaveLength(3); const [initiator1, initiator2, initiated] = records; diff --git a/core/test/network-records-to-devtools-log-test.js b/core/test/network-records-to-devtools-log-test.js index 4c2dead2fd..2d4af58d41 100644 --- a/core/test/network-records-to-devtools-log-test.js +++ b/core/test/network-records-to-devtools-log-test.js @@ -71,6 +71,7 @@ describe('networkRecordsToDevtoolsLog', () => { {url: 'https://example.com/2.js', timing: {requestTime: 5}}, {url: 'https://example.com/3.js', networkEndTime: -1}, {url: 'https://example.com/4.js', timing: {sendEnd: 1200}}, + {url: 'https://example.com/5.js', failed: true}, {}, ]; diff --git a/core/test/network-records-to-devtools-log.js b/core/test/network-records-to-devtools-log.js index e172bb0cc9..78c7b068d2 100644 --- a/core/test/network-records-to-devtools-log.js +++ b/core/test/network-records-to-devtools-log.js @@ -339,7 +339,8 @@ function getLoadingFailedEvent(networkRecord, index, normalizedTiming) { method: 'Network.loadingFailed', params: { requestId: getBaseRequestId(networkRecord) || `${idBase}.${index}`, - timestamp: normalizedTiming.networkEndTime, + timestamp: normalizedTiming.networkEndTime / 1000, + type: networkRecord.resourceType || undefined, errorText: networkRecord.localizedFailDescription || 'Request failed', }, };