Network.loadingFailed error preventing file from downloading

[nickhammond]

Started seeing a weird network/download issue with Ferrum and ended up pinpointing it to the Network.loadingFailed event but weirdly I'm not seeing anything get aborted in the network activity tab.

I'm seeing this Network.loadingFailed event which mentions that it was cancelled, could it be cancelled because a download was triggered?

◀ 10.84050099994056 {"method":"Network.loadingFailed","params":{"requestId":"4EF6FBF4E24DE266761996C9012FEB6E","timestamp":369165.481964,"type":"Document","errorText":"net::ERR_ABORTED","canceled":true}}
    ◀ 10.840605000033975 {"id":1066,"result":{"frameId":"668CED65D3AAA25B2594010F9317D1FD","loaderId":"4EF6FBF4E24DE266761996C9012FEB6E","errorText":"net::ERR_ABORTED"}}
    ◀ 10.842516000149772 {"method":"Page.frameStoppedLoading","params":{"frameId":"668CED65D3AAA25B2594010F9317D1FD"}}

It looks like the go_to method initially was listening to network level errors like DNS and connectivity. https://github.com/rubycdp/ferrum/commit/9217224d7079434cfdb18b54eadaac5df97f4da7#diff-2f9537c613f48bed5ff6ca273e2dac28886a32fe78dcd2dc7c7c798c891434d3R78 but was changed to just listen to any error coming back.

Since the browser most recently saw a Network.loadingFailed event but not a subsequent Network.loadingFinished or any other network event, just page and browser events, the response["errorText"] is still set even though the download has already started and is in progress. https://github.com/rubycdp/ferrum/blob/main/lib/ferrum/network.rb#L414

This causes the aborted error to be raised even though the download continues to go through and complete.

▶ 10.843002000125125 {"method":"DOM.getDocument","params":{"depth":0},"id":1067}
    ◀ 10.846949000144377 {"method":"Page.downloadWillBegin","params":{"frameId":"668CED65D3AAA25B2594010F9317D1FD","guid":"92505638-ce9e-41b2-9402-6725566c3421","url":"https://example.com/download/data.xlsx","suggestedFilename":"data.xlsx"}}
    ◀ 10.847257999936119 {"method":"Browser.downloadWillBegin","params":{"frameId":"668CED65D3AAA25B2594010F9317D1FD","guid":"92505638-ce9e-41b2-9402-6725566c3421","url":"https://example.com/download/data.xlsx","suggestedFilename":"data.xlsx"}}
    ◀ 10.860780999995768 {"id":1067,"result":{"root":{"nodeId":64,"backendNodeId":82,"nodeType":9,"nodeName":"#document","localName":"","nodeValue":"","childNodeCount":2,"documentURL":"https://example.com/","baseURL":"https://example.com/","xmlVersion":"","compatibilityMode":"NoQuirksMode"}}}
    ◀ 10.860869999974966 {"method":"Browser.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":0,"receivedBytes":0,"state":"inProgress"}}
    ◀ 10.8613090000581 {"method":"Page.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":0,"receivedBytes":0,"state":"inProgress"}}
{:goto_wait=>0.1}
{:options=>{:url=>"https://example.com/download/data.xlsx"}}
{:error=>"net::ERR_ABORTED"}
#<Ferrum::StatusError: Request to https://example.com/download/data.xlsx failed (net::ERR_ABORTED)>
Traceback (most recent call last):
/Users/n/.gem/ruby/2.7.8/bundler/gems/ferrum-020bd2570504/lib/ferrum/page.rb:121:in `go_to': Request to https://example.com/download/data.xlsx failed (net::ERR_ABORTED) (Ferrum::StatusError)
irb(main):002:0>     ◀ 10.86751600005664 {"method":"Page.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":0,"receivedBytes":0,"state":"inProgress"}}
    ◀ 10.867591999936849 {"method":"Browser.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":0,"receivedBytes":0,"state":"inProgress"}}
    ◀ 10.89020000002347 {"method":"Browser.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":0,"receivedBytes":22366,"state":"inProgress"}}
    ◀ 10.890261000022292 {"method":"Page.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":0,"receivedBytes":22366,"state":"inProgress"}}
    ◀ 10.890543000074103 {"method":"Page.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":0,"receivedBytes":22366,"state":"inProgress"}}
    ◀ 10.890619999961928 {"method":"Browser.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":0,"receivedBytes":22366,"state":"inProgress"}}
    ◀ 10.894420000026003 {"method":"Page.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":22366,"receivedBytes":22366,"state":"inProgress"}}
    ◀ 10.894460000097752 {"method":"Browser.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":22366,"receivedBytes":22366,"state":"inProgress"}}
    ◀ 10.897819000063464 {"method":"Page.downloadProgress","params":{"guid":"92505638-ce9e-41b2-9402-6725566c3421","totalBytes":22366,"receivedBytes":22366,"state":"completed"}}

[route]

I assume you are opening file directly with go_to?

[nickhammond]

@route Yes, to the https://example.com/download/data.xlsx URL after we've figured out what other parameters that need to be added to it.

[tisba]

I'm not 100% sure if I see the same issue. When updating to ferrum 0.14 (from 0.13) which I'm using indirectly via cuprite (0.14.3 → 0.15).

On GitHub Actions we now have a test consistently failing, although I'm having a hard time reproducing it locally. It is failing here:

visit download_file_fixture_path(file)

with:

[…]
Ferrum::StatusError:
  Request to http://app.localhost:41805//ds/94ty7cwb/download failed (net::ERR_ABORTED)
[…]

EDIT: Interestingly I can reproduce it on my x86 MacBook Pro 🤔

[route]

@tisba I'm pretty sure you started to use new Chrome 119 which broke something. Check your logs before on the successful build and after it started to fail for Chrome version.

[tisba]

Good point, I totally forgot about Chrome itself 🤦‍♂️

Can't access my M1 MacBook Pro right now to check the version where it worked. On my x86 MacBook Pro (using Docker) I can reproduce the issue with:

• Chromium 118.0.5993.0 - that's the version I had initially; exact same version I'm getting at GitHub Actions
• Chromium 119.0.6045.105 - fails also

Downgrading to Chromium 116.0.5845.180 fixed the issue locally.

I can find references to ERR_ABORTED in logs for all versions. It's a lot of output, anything in particular you want me to look for, @route?

[tisba]

Maybe there is an issue with Chrome versions, but this feels more related to upgrading ferrum (0.13 -> 0.14) and/or cuprite (0.14.3 → 0.15). With the identical Chrome version it works before the update and breaks consistently after.

[route]

I doubt that because you can see latest builds of ferrum https://github.com/rubycdp/ferrum/commits/main

[tisba]

Need some more time building a simplified example. At least in our case, the issue is not occuring when staying at ferrum 0.13 and cuprite 0.14.3, both locally on my MacBook Pro (x86) as well as on GitHub Actions 🤷

[route]

@nickhammond can you tell me your Chrome version?

[nickhammond]

@route I'll have to test again to ensure it's still happening since I ended up patching and pointing to my own fork.

Chrome: 118.0.5993.70 Patch: https://github.com/nickhammond/ferrum/commit/b2bc60641382673326d11fd4057727ebf8d44107

[route]

Chrome 119 started to send:

{"method":"Page.frameStoppedLoading","params":{"frameId":"69FE7B40C52D828E8A4681686395EAC8"}}

for the main request which was always missing before. In fact Chrome was always returning an error for the main request:

◀ 0.6014469999936409 {"method":"Network.loadingFailed","params":{"requestId":"B6E447A057194D37B4873953C9448868","timestamp":353280.996004,"type":"Document","errorText":"net::ERR_ABORTED","canceled":true}}
◀ 0.6015239999978803 {"id":1011,"result":{"frameId":"69FE7B40C52D828E8A4681686395EAC8","loaderId":"B6E447A057194D37B4873953C9448868","errorText":"net::ERR_ABORTED"}}

but was missing to send Page.frameStoppedLoading this is why it broke now.

I believe it works like this because it downloads file in the subprocess, and it doesn't make sense for it to continue main request since it's the same file, so it always cancels main request and starts subprocess to download file. When download is finished the browser gets notification or in case of headless instance Page.downloadProgress is returned with status completed.

1. Technically speaking page.go_to("/filename") is always failing when we download file because errorText's returned and by protocol it means: User friendly error message, present if and only if navigation has failed. So we must raise an error. I understand that it's frustrating, I think in this case we can consider net::ERR_ABORTED as due to user action or download and not raise an error.
2. A file can be 100Kb or 1Gb and currently there's no option to wait until download is finished. We must implement this feature.

/cc @tisba @nickhammond

[nickhammond]

@route Nice digging, appreciate the context! Yah, when I was looking through that network log I wasn't entirely sure what looked normal and what didn't.

[nickhammond]

@route Nice work! I'll update our app to point to this version.