1937367 - After resuming laptop from overnight sleep/standby/Lid Close, all pages intermittently stop loading for 1 minute(other browser on the same machine loads pages just fine)

Status: VERIFIED FIXED

(Core :: Networking, defect, P2)

Description

[Mayank Bansal]

Profile with networking preset : https://share.firefox.dev/4gc8v6b

I was trying to open: https://treeherder.mozilla.org/perfherder/graphs?highlightAlerts=1&highlightChangelogData=1&highlightCommonAlerts=0&replicates=0&selected=83615,1917694797&series=autoland,83615,1,13&timerange=5184000&zoom=1733946312945,1734292815159,562.8531853231075,834.1984365042341

The page wont load... Then i tried opening google.com and that wouldnt load. Even the profile took a long time to capture.
I also sometimes get hang while shutting down the browser - I get the message "another instance of firefox is already running" message.

Filing under networking, but this may be due to other issues.

Comment 1

[Mayank Bansal]

Attachment: about:support

Comment 2

[Mayank Bansal]

This is with the latest Nightly only. It only reproduced a few times, and I dont see it anymore.
I suspect it was a "one-time" activity from the patches in Bug 1933053

Comment 3

[jonzn4SUSE]

Attachment: nightly_Screenshot_20241215_100601.png

Not able to replicate issue.

Operating System: openSUSE Leap 15.6
KDE Plasma Version: 5.27.11
KDE Frameworks Version: 5.115.0
Qt Version: 5.15.12
Kernel Version: 6.4.0-150600.23.30-default (64-bit)
Graphics Platform: X11
Processors: 16 × AMD Ryzen 7 PRO 6850HS with Radeon Graphics
Memory: 62.1 GiB of RAM
Graphics Processor: AMD Radeon Graphics
Manufacturer: HP
Product Name: HP EliteBook 865 16 inch G9 Notebook PC

Comment 4

[Mayank Bansal]

Another profile with networking preset logging: https://share.firefox.dev/3ZvhvMs

Comment 5

[Randell Jesup [:jesup] (needinfo me)]

This line in the markers from the last profile implies ublock origin was involved. This is the first event that happens when treeherder finally gets unblocked after sitting for 15+s

Extension Suspend - onBeforeRequest https://treeherder.mozilla.org/jobs?repo=try by [e-mail] (chanId: 11132)

Can you try disabling uBlock Origin (and other extensions?)

Comment 6

[Mayank Bansal]

I disabled ublock and could still repro : https://share.firefox.dev/4iINhyr
But as i saud, this is intermittent and started in the last 1-2 days only.

Comment 7

[Mayank Bansal]

• Here is another profile (with all extensions enabled) where pages just stopped loading while i was browsing. I started the profiler after maybe 30 seconds of "hang". https://share.firefox.dev/4iDhyP2
• Another profile with all threads and I/O: https://share.firefox.dev/3VIULrd

Comment 8

[Mayank Bansal]

Attachment: log.txt-main.22352.zip

Networking log. I started logging just after startup. My usual profile with all addons.

Comment 9

[Mayank Bansal]

In many such cases, when i close the browser and restart, I get the "Firefox is already running" message. When i force close Firefox and start Firefox again, network does not load.
I checked the "dependency cycle" using Windows task manager, and it said that Firefox was waiting to complete "Network I/O" on two threads of one of the Firefox processes (I chose the Firefox process with highest memory use so I am guessing it must be the parent-process)

Comment 10

[Mayank Bansal]

Attachment: log.txt-main.23060.zip

OK, this should be hopefully a better log that i captured.

This contains the networking + websockets+http3 logging presets.

I started logging when pages opened normally. Then I did a bit of browsing. Then the pages stopped loading for maybe 15-20 seconds. Then they eventually all loaded.

This log captures all of that.

rjesup, was this useful?

Comment 11

[Mayank Bansal]

This seem to occur after i resume my laptop after suspend/sleep. I specially notice this after i open my laptop in the morning after i close the lid in the night.
Only Firefox is affected. This may only occur on Win11 24H2 version.

Comment 12

[Mayank Bansal]

Here is another profile with network preset logging: https://share.firefox.dev/4ah8HP3

Comment 13

[Randell Jesup [:jesup] (needinfo me)]

Could one of you take a look? Thanks

Comment 14

[Valentin Gosu [:valentin]]

Looking at the user triggered channels, they seem to be canceled by this stack:

XMLHttpRequest.abort
stopresource://gre/modules/SearchSuggestionController.sys.mjs:352:7
cancelQueryresource:///modules/UrlbarProviderSearchSuggestions.sys.mjs:320:14
js::RunScript

That said, I would have expected some DNS resolutions to happen, but I see none of that in the profile.
And the Socket thread is doing next-to-nothing.

@Mayank, thank you for this report.
If possible, could you start profiling before suspending the computer? Then capturing immediately after resuming?
Thanks!

Comment 15

[Mayank Bansal]

https://share.firefox.dev/4ampK2x

I started network preset logging . Then i closed down the lid and went to sleep. Woke up in the morning and captured the profile.
Let me know if it works for you.
Edit: I didnt try to open any page after waking up, which is why the profile is sort of empty. Will retry again tomorrow.

Comment 16

[Kershaw Chang [:kershaw]]

(In reply to Mayank Bansal from comment #15)

https://share.firefox.dev/4ampK2x

I started network preset logging . Then i closed down the lid and went to sleep. Woke up in the morning and captured the profile.
Let me know if it works for you.
Edit: I didnt try to open any page after waking up, which is why the profile is sort of empty. Will retry again tomorrow.

The profile indicates that after 2025-01-21 01:48:08.381965576 UTC, all proxy resolutions are blocked, with the last successful resolution logged at that timestamp.

2025-01-21 01:48:08.381965576 UTC - [Parent Process 15988: GeckoMain]: D/nsHttp nsHttpChannel::OnProxyAvailable [this=2088ae17c00 pi=0 status=0 mStatus=0]

For example, TRR request 2089037f100 attempts to resolve the proxy at 01:48:08.402730712 UTC but is subsequently canceled, as shown in the logs. Could you please add proxy:5 to the MOZ_LOG environment variable and capture the HTTP logs again? Additionally, are you able to reproduce this issue using a clean profile?

2025-01-21 01:48:08.402730712 UTC - [Parent Process 15988: GeckoMain]: D/nsHttp TRRServiceChannel::ResolveProxy [this=2089037f100]
2025-01-21 01:48:09.886917480 UTC - [Parent Process 15988: TRR Background]: D/nsHttp TRRServiceChannel::Cancel [this=2089037f100 status=804b0055]
2025-01-21 01:48:09.887862792 UTC - [Parent Process 15988: GeckoMain]: D/nsHttp TRRServiceChannel::OnProxyAvailable [this=2089037f100 pi=0 status=804b0055 mStatus=804b0055]

Comment 17

[Mayank Bansal]

I have tried to get a profile for the last two days by starting the profiler, suspending, and then capturing the profile in the morning.
However, on resuming the browser, it is able to connect to the network. Maybe the act of keeping the browser open and profiler running prevents my laptop from truely suspending?
(keeping the needinfo)

Comment 18

[Mayank Bansal]

Valentin, I have been trying to repro for 3 days now. But it looks like if I keep Firefox open when closing the lid of my laptop, on waking up Firefox can access network normally. So I think to repro this issue, I need to close Firefox.
What can I try next here?

Comment 19

[Valentin Gosu [:valentin]]

How did you capture the profile before? Does that method still work?
It would be good if you also manage to add proxy:5 to the module list.

Comment 20

[Mayank Bansal]

(In reply to Valentin Gosu [:valentin] (he/him) from comment #19)

How did you capture the profile before? Does that method still work?
It would be good if you also manage to add proxy:5 to the module list.

Previously, i would close Firefox and let the laptop suspend. Then in the morning i would start firefox and capture logs. that should still work i guess. (So basically capture the log just after startup). I will add proxy:5. I will capture something tomorrow morning.

Is there a way to log during startup? Some sort of logging that begins with the launch of the browser?

Comment 21

[Mayank Bansal]

Hmmm.... https://firefox-source-docs.mozilla.org/networking/http/logging.html may be onto something

I will try using this command line argument:

"c:\Program Files\Mozilla Firefox\firefox.exe" -MOZ_LOG=nsSocketTransport:5,EarlyHint:5,neqo_transport:::3,nsWebSocket:5,nsHostResolver:5,cache2:5,neqo_http3:::5,nsHttp:5,proxy:5,timestamp,sync,profilerstacks -MOZ_LOG_FILE=%TEMP%\log.txt

Should I add the "profilerstacks" at the end? Does this look correct to you?

Comment 22

[Valentin Gosu [:valentin]]

Ah, I understand now.
Yes, getting the proxy:5 logs even after the resume may help us find the problem.
Don't think logging the browser startup would help here - but you can do it with the MOZ_LOG env variable. You can even profile during startup https://profiler.firefox.com/docs/#/./guide-startup-shutdown

Comment 23

[Valentin Gosu [:valentin]]

Latest logs from Mayank.
https://drive.google.com/drive/folders/1lJUtOm4oRH40CWWFLXOd-yiFbJgJU155?usp=drive_link

Comment 24

[Valentin Gosu [:valentin]]

Looking at the logs, I see:

2025-01-29 15:37:20.129000 UTC - [Parent 30008: Main Thread]: V/nsHttp TRRServiceChannel::ResolveProxy [this=1e4c5033a00]
...
2025-01-29 15:37:21.696000 UTC - [Parent 30008: TRR Background]: D/nsHostResolver TRR: 1e4c50efb60 canceling Channel 1e4c5033a40 bugzilla.mozilla.org 28 status=804b0055
2025-01-29 15:37:21.696000 UTC - [Parent 30008: TRR Background]: V/nsHttp TRRServiceChannel::Cancel [this=1e4c5033a00 status=804b0055]
...
2025-01-29 15:37:21.696000 UTC - [Parent 30008: Main Thread]: D/proxy pac thread callback did not provide information 804B0055

later:

2025-01-29 15:38:33.329000 UTC - [Parent 30008: Main Thread]: D/nsHttp nsHttpChannel::ResolveProxy [this=1e4c598d400]
2025-01-29 15:38:33.329000 UTC - [Parent 30008: Main Thread]: D/proxy nsPACMan::AsyncGetProxyForURI reload as scheduled
2025-01-29 15:38:33.329000 UTC - [Parent 30008: Main Thread]: D/proxy nsPACMan::LoadPACFromURI aSpec: , aResetLoadFailureCount: false
2025-01-29 15:38:33.329000 UTC - [Parent 30008: Main Thread]: D/proxy network.proxy.type pref retrieved: 4
2025-01-29 15:38:33.329000 UTC - [Parent 30008: Main Thread]: D/proxy network.proxy.type pref retrieved: 4
2025-01-29 15:38:33.329000 UTC - [Parent 30008: Main Thread]: D/proxy pac not available, use DIRECT

Mayank says the configured proxy setting was auto detect proxy settings for this network, so presumably the OS settings are configured for WPAD.
The proxy code isn't LOGging too much, so I assume the problem is somewhere in the proxy code. We're probably encountering an error, but not calling the callback.

I asked Mayank to also test with no proxy

Comment 25

[Valentin Gosu [:valentin]]

Mayank reports that setting the proxy to no proxy got rid of the resume hang.

Comment 26

[Valentin Gosu [:valentin]]

I think we need to add more proxy logging to figure out what is erroring after resume.

Comment 27

[Valentin Gosu [:valentin]]

Attachment: Bug 1937367 - Extra proxy logging r=#necko

Also removes unused nsAsyncBridgeRequest

Comment 28

[Valentin Gosu [:valentin]]

I went through the most recent logs and found the following:

// First call to ResolveProxy
2025-01-29 15:37:20.127000 UTC - [Parent 30008: TRR Background]: V/nsHttp TRRServiceChannel::ResolveProxy [this=1e4c5033a00]
...
// Call failed
2025-01-29 15:37:21.696000 UTC - [Parent 30008: TRR Background]: V/nsHttp TRRServiceChannel::Cancel [this=1e4c5033a00 status=804b0055]
...
// This thread is blocked maybe?
2025-01-29 15:38:22.629000 UTC - [Parent 30008: ProxyResolution]: D/proxy nsPACMan::GetPACFromDHCP DHCP option 252 query failed with result -2147221231
....
2025-01-29 15:38:27.651000 UTC - [Parent 30008: Main Thread]: D/proxy OnStreamComplete: entry
2025-01-29 15:38:27.651000 UTC - [Parent 30008: Main Thread]: D/proxy OnStreamComplete: unable to load PAC, retry later
2025-01-29 15:38:27.651000 UTC - [Parent 30008: Main Thread]: D/proxy OnLoadFailure: retry in 5 seconds (1 fails)
...
2025-01-29 15:38:27.712000 UTC - [Parent 30008: Main Thread]: V/nsHttp TRRServiceChannel::OnProxyAvailable [this=1e4b370da00 pi=0 status=0 mStatus=0] (first good)

I looked around for some info about GetPACFromDHCP getting stuck, and found this chrome bug: Chrome hangs after waking up from sleepswitching network when using proxy auto-detect and have virtual adapters enabled 40542477 which seems to describe a very similar issue.

I think the problem is that DhcpRequestParams is hanging simlar to Chrome, and this is blocking the ProxyResolution thread here.

Chrome uses multiple threads to avoid hanging. I'm wondering if we could execute this on a background thread that is not the ProxyResolution thread instead.

Comment 29

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/mozilla-central/rev/bbff13f39637
Extra proxy logging r=necko-reviewers,kershaw

Comment 30

[Serban Stanca [:SerbanS]]

https://hg.mozilla.org/mozilla-central/rev/bbff13f39637

Comment 31

[Valentin Gosu [:valentin]]

Attachment: Bug 1937367 - Make sure to not query local or offline adapters r=#necko

Comment 32

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/be8fed2bb18f
Make sure to not query local or offline adapters r=necko-reviewers,kershaw

Comment 33

[Valentin Gosu [:valentin]]

Mayank, once this gets merged to central, I'd appreciate it if you tried to reproduce again and captured another profile.
Add dhcpUtils:5 to the modules list.
Thanks!

Comment 34

[Cristina Horotan [:chorotan]]

https://hg.mozilla.org/mozilla-central/rev/be8fed2bb18f

Comment 35

[Mayank Bansal]

(In reply to Valentin Gosu [:valentin] (he/him) from comment #33)

Mayank, once this gets merged to central, I'd appreciate it if you tried to reproduce again and captured another profile.
Add dhcpUtils:5 to the modules list.
Thanks!

shared the logs privately on chat.

Comment 36

[Mayank Bansal]

Just for clarity: I can still repro this.

Comment 37

[Valentin Gosu [:valentin]]

Thanks. I'll have a look at fixing this next week. It does seem to match Chrome's problem exactly, with DhcpRequestParams hanging.

I intend to call DhcpRequestParams and have the ProxyResolution thread wait on a condition variable with a timeout.

Comment 38

[Valentin Gosu [:valentin]]

Attachment: Bug 1937367 - Add timeout when calling DhcpRequestParams to get proxy settings r=#necko

Comment 39

[Greg Hess]

(Commenting on User Story)

platform-scheduled:2025-12-31

Comment 40

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/52339d7235b9
Add timeout when calling DhcpRequestParams to get proxy settings r=necko-reviewers,sunil

Comment 41

[Serban Stanca [:SerbanS]]

https://hg.mozilla.org/mozilla-central/rev/52339d7235b9

Comment 42

[Mayank Bansal]

I havent reproduced this issue after the latest patch.

Comment 43

[Valentin Gosu [:valentin]]

Marking verified based on comment 42