[Bug]: NetworkManager._emitLoadingFinished/_emitLoadingFailed never called when ResponseReceivedExtraInfo follows ResponseReceived

[kadaan]

Bug description

Steps to reproduce the problem:

1. Make a puppeteer request where the responseReceivedExtraInfo occurs after the responseReceived, ie.

[
    {
      "method": "Network.requestWillBeSent",
      "params": {
        "requestId": "1360.2",
        "loaderId": "9E86B0282CC98B77FB0ABD49156DDFDD",
        "documentURL": "http://this.is.the.start.page.com/",
        "request": {
          "url": "http://this.is.a.test.com:1080/test.js",
          "method": "GET",
          "headers": {
            "Accept-Language": "en-US,en;q=0.9",
            "Referer": "http://this.is.the.start.page.com/",
            "User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.0 Safari/537.36"
          },
          "mixedContentType": "none",
          "initialPriority": "High",
          "referrerPolicy": "strict-origin-when-cross-origin",
          "isSameSite": false
        },
        "timestamp": 10959.020087,
        "wallTime": 1649712607.861365,
        "initiator": {
          "type": "parser",
          "url": "http://this.is.the.start.page.com/",
          "lineNumber": 9,
          "columnNumber": 80
        },
        "redirectHasExtraInfo": false,
        "type": "Script",
        "frameId": "60E6C35E7E519F28E646056820095498",
        "hasUserGesture": false
      }
    },
    {
      "method": "Network.requestWillBeSentExtraInfo",
      "params": {
        "requestId": "1360.2",
        "associatedCookies": [],
        "headers": {
          "Host": "this.is.a.test.com:1080",
          "Connection": "keep-alive",
          "Pragma": "no-cache",
          "Cache-Control": "no-cache",
          "Accept-Language": "en-US,en;q=0.9",
          "User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/98.0.4758.0 Safari/537.36",
          "Accept": "*/*",
          "Referer": "http://this.is.the.start.page.com/",
          "Accept-Encoding": "gzip, deflate"
        },
        "connectTiming": {
          "requestTime": 10959.023904
        },
        "clientSecurityState": {
          "initiatorIsSecureContext": false,
          "initiatorIPAddressSpace": "Unknown",
          "privateNetworkRequestPolicy": "Allow"
        }
      }
    },
    {
      "method": "Network.responseReceived",
      "params": {
        "requestId": "1360.2",
        "loaderId": "9E86B0282CC98B77FB0ABD49156DDFDD",
        "timestamp": 10959.042529,
        "type": "Script",
        "response": {
          "url": "http://this.is.a.test.com:1080",
          "status": 200,
          "statusText": "OK",
          "headers": {
            "connection": "keep-alive",
            "content-length": "85862"
          },
          "mimeType": "text/plain",
          "connectionReused": false,
          "connectionId": 119,
          "remoteIPAddress": "127.0.0.1",
          "remotePort": 1080,
          "fromDiskCache": false,
          "fromServiceWorker": false,
          "fromPrefetchCache": false,
          "encodedDataLength": 66,
          "timing": {
            "requestTime": 10959.023904,
            "proxyStart": -1,
            "proxyEnd": -1,
            "dnsStart": 0.328,
            "dnsEnd": 2.183,
            "connectStart": 2.183,
            "connectEnd": 2.798,
            "sslStart": -1,
            "sslEnd": -1,
            "workerStart": -1,
            "workerReady": -1,
            "workerFetchStart": -1,
            "workerRespondWithSettled": -1,
            "sendStart": 2.982,
            "sendEnd": 3.757,
            "pushStart": 0,
            "pushEnd": 0,
            "receiveHeadersEnd": 16.373
          },
          "responseTime": 1649712607880.971,
          "protocol": "http/1.1",
          "securityState": "insecure"
        },
        "hasExtraInfo": true,
        "frameId": "60E6C35E7E519F28E646056820095498"
      }
    },
    {
      "method": "Network.responseReceivedExtraInfo",
      "params": {
        "requestId": "1360.2",
        "blockedCookies": [],
        "headers": {
          "connection": "keep-alive",
          "content-length": "85862"
        },
        "resourceIPAddressSpace": "Private",
        "statusCode": 200,
        "headersText": "HTTP/1.1 200 OK\r\nconnection: keep-alive\r\ncontent-length: 85862\r\n\r\n"
      }
    },
    {
      "method": "Network.loadingFinished",
      "params": {
        "requestId": "1360.2",
        "timestamp": 10959.060708,
        "encodedDataLength": 85928,
        "shouldReportCorbBlocking": false
      }
    }
]

2. No RequestFinished event is emitted (NetworkManager._emitLoadingFinished is never called)

Analysis

1. responseReceived dev tools protocol event occurs, NetworkManager._onResponseReceived is called. Since event.hasExtraInfo == true and the responseReceivedExtraInfo dev tools protocol event has not occurred, responseReceived event is added to queueEventGroup
2. responseRecievedExtraInfo dev tools protocol event occurs, NetworkManager._onResponseReceivedExtraInfo is called. Since responseReceived dev tools protocol event is in queueEventGroup, the NetworkManager._emitResponseEvent is called. Since loadingFinished dev tools protocol event has not occurred, the NetworkManager._emitLoadingFinished is not called
3. loadingFinished dev tools protocol event occurs, NetworkManager._onLoadingFinished is called. Since responseReceived dev tools protocol event is in queueEventGroup, the loadingFinished dev tools protocol event is added to the event in queueEventGroup. NetworkManager._emitLoadingFinished is not called.

Side Effects

1. Memory leak, as the entry in queueEventGroup is never deleted.

Potential Fix

1. Remove event from queueEventGroup after NetworkManager._emitResponseEvent is called in NetworkManager._onResponseReceivedExtraInfo

Puppeteer version

13.1.3, this issue exists in 12.0.0 and higher

Node.js version

17.3.1

npm version

8.3.0

What operating system are you seeing the problem on?

macOS

Related PRs

#7640
#7764

Relevant log output

The following logs are from "evaluate and log" breakpoints in Intellij at these locations:

1360.2: NetworkManager: _onRequestWillBeSent
1360.2: NetworkManager: _onRequest
1360.2: Page: Request
1360.2: NetworkManager: _onResponseReceived
1360.2: NetworkManager: _onResponseReceivedExtraInfo
1360.2: Page: Response
1360.2: NetworkManager: _onLoadingFinished

[kadaan]

@josepharhar @OrKoN Can you please confirm this issue?

[josepharhar]

Memory leak, as the entry in queueEventGroup is never deleted.

Remove event from queueEventGroup after NetworkManager._emitResponseEvent is called in NetworkManager._onResponseReceivedExtraInfo

This makes sense to me

[kadaan]

@josepharhar Want us to create a PR or do you guys want to tackle it?

[josepharhar]

Please open a PR

[kadaan]

@josepharhar There you go. Sorry for the closed PR, needed to get my email right on the commit so that it matched my individual CLA.

[jribbens]

Any chance of a release with this fix in? :-) Puppeteer has been broken for me since v12 due to this.

[jribbens]

Thank you, excellent service ;-)

[OrKoN]

I believe this is now closed? thanks a lot for the PR and the bug report!