Closed Bug 1680688 Opened 3 years ago Closed 3 years ago

Firefox 83 loses connection when network is changed between 1 requiring proxy (VPN) and 1 without proxy

Categories

(Core :: Networking, defect, P2)

Firefox 83
x86_64
Windows 10
defect

Tracking

()

RESOLVED FIXED
87 Branch
Tracking Status
firefox87 --- fixed

People

(Reporter: m2f2, Assigned: kershaw)

Details

(Whiteboard: [necko-triaged])

Attachments

(5 files, 3 obsolete files)

4.08 MB, application/octet-stream
Details
8.33 MB, application/octet-stream
Details
39.90 KB, application/octet-stream
Details
1.03 MB, application/x-zip-compressed
Details
48 bytes, text/x-phabricator-request
Details | Review

+++ This bug was initially created as a clone of Bug #726211 +++
+++ Regression from Firefox 81 (or was it 82?) which used to work perfectly +++

User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:83.0) Gecko/20100101 Firefox/83.0

Steps to reproduce: use case #1

Changed network - from normal network (direct internet connection)
to VPN (for example)
"Use system proxies" on all the time
Lose network connection and reconnect with Firefox running all the time

Steps to reproduce: use case #2

Changed network - from normal network (direct internet connection)
to VPN (for example)
"Use (local proxy.pac)" on all the time
"local proxy.pac" is re-created by the VPN startup managing the "VPN/company" settings and reset to an empty line with "DIRECT" on VPN shutdown
Lose network connection and reconnect with Firefox running all the time

either way:

Actual results:
Firefox can't load any web page and requires restart to start working again

Expected results:
Firefox 83 should be able to detect resetted/changed network connection and react
Firefox 81 (or 82?) did react and work seamlessly
Edgium/Chrome: work seamlessly

Kershaw, can you take a look?

Flags: needinfo?(kershaw)

Hi Reporter,

Since you said that Firefox worked before 83, could you try to use mozregression to figure out since when Firefox has this problem? In case this is not easy to reproduce, could you try to capture http log at the point when you active VPN? Please also add nsNotifyAddr:5 to MOZ_LOG.
After the VPN is activated and Firefox is not working, please try to access some simple website (example.com). The log should be able to tell us what's wrong.

Thanks.

Flags: needinfo?(kershaw) → needinfo?(m2f2)

Sorry can't get past mozregression being flagged as malware (corporate PC here).
Please close the bug.

Flags: needinfo?(m2f2)

(In reply to m2f2 from comment #3)

Sorry can't get past mozregression being flagged as malware (corporate PC here).
Please close the bug.

Are you still able to reproduce this? If mozregression is not feasible, could you try to get the http log?
Thanks.

Flags: needinfo?(m2f2)

(In reply to Kershaw Chang [:kershaw] from comment #4)

(In reply to m2f2 from comment #3)

Sorry can't get past mozregression being flagged as malware (corporate PC here).
Please close the bug.

Are you still able to reproduce this? If mozregression is not feasible, could you try to get the http log?
Thanks.

Attached is what I see, hopefully I followed the steps right.

Attached file onvpn.txt-child.1236.moz_log.zip (obsolete) —
Flags: needinfo?(m2f2)

Here are my steps:
Initial state: START LOGGING while VPN is UP
2020-12-15 16:05:55 UTC = access page https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging == SUCCESS
2020-12-15 16:07:10 UTC = CLOSE VPN
2020-12-15 16:07:30 UTC = reload page https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging == FAIL
2020-12-15 16:08:20 UTC = reload pac
2020-12-15 16:08:40 UTC = reload page https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging == SUCCESS
2020-12-15 16:09:20 UTC = start VPN
2020-12-15 16:09:40 UTC = VPN connected
2020-12-15 16:10:00 UTC = reload page https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging == FAILED
2020-12-15 16:12:34 UTC = reload pac
2020-12-15 16:12:54 UTC = reload page https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging == SUCCESS

Thanks for the log!

It looks like that Firefox didn't detect the network change caused by turning and off VPN.
Could you try to get the log when switch VPN on and off? This time please only set MOZ_LOG' to 'nsNotifyAddr:5.

Flags: needinfo?(m2f2)

Log of connecting to VPN then disconnecting

Thanks for the log. This is useful.

I have some questions: how did you reload pac? I assume the proxy setting in firefox is always Use system proxy, right? When you switched on/off vpn, was proxy setting in system also changed?
I also noticed two http requests http://proxy-reload.firefox.invalid/proxy.pac from the log. It seems Firefox tried to reload the pac when the VPN was turned on and off, but these two requests were failed.

Attached file vpn-on-off.zip (obsolete) —
Flags: needinfo?(m2f2)

(In reply to Kershaw Chang [:kershaw] from comment #10)

Thanks for the log!

It looks like that Firefox didn't detect the network change caused by turning and off VPN.
Could you try to get the log when switch VPN on and off? This time please only set MOZ_LOG' to 'nsNotifyAddr:5.

New log attached >>> https://bugzilla.mozilla.org/attachment.cgi?id=9193438
Please note that Firefox actually knows about the network change [2020-12-16 09:09:06.101000 UTC], and it correctly detects all new DNS suffixes brought in by VPN/DHCP.

Main pointers to the log:

  • 2020-12-16 09:08:16 UTC - load https://developer.mozilla.org/en-US/ - SUCCESS
  • 2020-12-16 09:08:50 UTC - start vpn
  • 2020-12-16 09:09:06.101000 UTC - [Parent 10660: Unnamed thread 0000024E51A8AC00]: D/nsNotifyAddr check status of all network adapters
  • 2020-12-16 09:09:06.245000 UTC - [Parent 10660: Unnamed thread 0000024E51A8AC00]: D/nsNotifyAddr found DNS suffix-XXXXXXX.com
  • 2020-12-16 09:09:06.245000 UTC - [Parent 10660: Unnamed thread 0000024E51A8AC00]: D/nsNotifyAddr found DNS suffix-lan
  • 2020-12-16 09:09:12 UTC - vpn connection completed
  • 2020-12-16 09:10:01 UTC - reload https://developer.mozilla.org/en-US/ - FAIL (timeout)
  • 2020-12-16 09:12:43 UTC - reload pac
  • 2020-12-16 09:12:43 UTC - reload https://developer.mozilla.org/en-US/ - SUCCESS
  • 2020-12-16 09:13:24 UTC - stop vpn
  • 2020-12-16 09:13:31 UTC - vpn disconnected
  • 2020-12-16 09:14:09 UTC - reload https://developer.mozilla.org/en-US/ - FAIL (proxy server not found)
  • 2020-12-16 09:14:51 UTC - reload pac
  • 2020-12-16 09:14:51 UTC - reload https://developer.mozilla.org/en-US/ - SUCCESS

Thanks!

The log did show that firefox detect network changes - that's good.
It also shows that firefox failed to load the pac file, no matter VPN is on or off. It looks like the host name proxy-reload.firefox.invalid is designed to be failed...

2020-12-16 09:14:54.126000 UTC - [Parent 10660: DNS Resolver #1]: E/nsHostResolver DNS lookup thread - lookup completed for host [proxy-reload.firefox.invalid]: failure: unknown host.

Could you answer my questions in comment #12?
Thanks.

Flags: needinfo?(m2f2)
Attached file vpn-on-off-sysproxy.zip (obsolete) —
Flags: needinfo?(m2f2)

The "proxy-reload.firefox.invalid" behavior is due to the "RELOAD PAC BUTTON" extension >>> https://addons.mozilla.org/en-US/firefox/addon/reload-pac-button/
The code actually switches proxy to an invalid entry, then resets to the previous value, forcing re-reading it from scratch.

I'm repeating the same test removing the RELOAD PAC extension and using "Use system proxy" with timestamp,sync,nsHttp:5,nsNotifyAddr:5,nsHostResolver:5 >>> https://bugzilla.mozilla.org/attachment.cgi?id=9193451

As a side note, I'm now on Firefox 84 (auto update kicked in, argh!) - but I see the same behavior.

Logged actions:

Attachment #9193438 - Attachment is obsolete: true
Attachment #9193291 - Attachment is obsolete: true

Hi,

Thanks for the log and the clear explanation. However, it's unclear to me why Firefox can't reload the PAC automatically after the VPN is activated.
So, I create a test build with more logs here. Could you try to reproduce this problem and get the http log again with this build?
Please set MOZ_LOG to timestamp,sync,nsHttp:5,nsNotifyAddr:5,nsHostResolver:5,proxy:5 in order to collect some logs about reloading PAC.

Let's also simplify the STR as below.

  1. Make sure VPN is disabled.
  2. Start logging.
  3. Load https://developer.mozilla.org/en-US/
  4. Start VPN
  5. Wait about 10s to allow Firefox to reload the PAC.
  6. Load https://developer.mozilla.org/en-US/ again.
  7. Stop logging.

Thanks again for your help!

Flags: needinfo?(m2f2)
Attached file nightly.zip

Done, VPN was up at 2020-12-18 17:45:52 UTC

Attachment #9193451 - Attachment is obsolete: true
Flags: needinfo?(m2f2)

Can you take a look?

Flags: needinfo?(kershaw)

(In reply to m2f2 from comment #19)

Created attachment 9193965 [details]
nightly.zip

Done, VPN was up at 2020-12-18 17:45:52 UTC

Sorry for the long delay. I've checked the log, which shows that the PAC URI is not available when Firefox received a networking change event. I guess the solution is adding a delay before reading it. Could you try to follow the steps in comment #18 to test again with this test build? The delay is adjustable by this pref network.proxy.reload_pac_delay. You could try to adjust the value shorter or longer to see if my theory is correct or not.

Thanks!

Flags: needinfo?(kershaw) → needinfo?(m2f2)

You nailed it! Firefox (now I'm on 85.0) with the default value (1800) and the standard "use system proxy" works well.

I also stressed it by navigating just at the same time when the vpn connection was being activated, and in the end worked as well, even if rather slowly (I mean, as slowly as the rest of the system when the VPN is messing up with the network stack in order to set it up). After the VPN connection was stable and up (or down) everything was normal.

Well done - thanks.
I'm keeping the nightly edition, and will wait for the patch to be included in a final release.

Ciao!

Flags: needinfo?(m2f2)

(In reply to m2f2 from comment #22)

You nailed it! Firefox (now I'm on 85.0) with the default value (1800) and the standard "use system proxy" works well.

I also stressed it by navigating just at the same time when the vpn connection was being activated, and in the end worked as well, even if rather slowly (I mean, as slowly as the rest of the system when the VPN is messing up with the network stack in order to set it up). After the VPN connection was stable and up (or down) everything was normal.

Well done - thanks.
I'm keeping the nightly edition, and will wait for the patch to be included in a final release.

Ciao!

Thanks for your help!
I'll create a patch soon.

Assignee: nobody → kershaw
Severity: normal → S4
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Priority: -- → P2
Whiteboard: [necko-triaged]
Pushed by kjang@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/5fdf7063a1f1
Add a delay before we reload PAC url r=necko-reviewers,valentin
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 87 Branch

Hi,

I'm facing a problem with similar symptoms as m2f2.

When I am disconnected from VPN, I am able to connect to websites properly. But when I connect to my company's VPN, the network still works for about 30 secs, but then it cannot connect anymore. It seems to just hang and the loading icon. My company's network routes through a web proxy.

I have run the logs and noticed that there are frequent and repeated occurrence of:

2021-12-23 03:21:53.672000 UTC - [Parent 16068: Socket Thread]: D/nsSocketTransport SocketContext::TimeoutIn socket=17fcfb7e800, timeout=65535s
2021-12-23 03:21:53.672000 UTC - [Parent 16068: Socket Thread]: D/nsSocketTransport   not engaged

The issue occurs on FireFox nightly 97. It's been occurring for the past few days.
I tested on stable FireFox 95 and Brave browser, and it works fine.

I can't attach the log file as it is too huge. I've uploaded to my online file storage and will keep it there until ticket is resolved.

https://od.lk/f/ODlfMTYzNDkyNDFf

This is a 7z archive which contains 1 log file only.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: