1495024 - Firefox checks to determine proxy settings on every request.

Status: VERIFIED FIXED

(Core :: Networking: HTTP, defect, P2)

Description

[James]

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:64.0) Gecko/20100101 Firefox/64.0
Build ID: 20180928100051

Steps to reproduce:

Configure Firefox 64.0a1 (2018-09-28) (nightly) to "Auto-Detect proxy settings for this network" 


Actual results:

Browsing sites such as reddit.com or other dynamic sites like YouTube were very slow. In monitoring network activity the HTTPS requests themselves were not slow, however it seemed that Firefox was hanging before sending a batch of requests. 

Changing Firefox back to 'No Proxy' resolved this issue


Expected results:

Firefox should only Auto-detect the proxy one time at startup instead of with each request.

Comment 1

[Daniel Stenberg [:bagder]]

Thanks for the report!

So isn't there also the possibility that the proxy itself was slow here?

To allow us to try to reproduce and understand what happened here, can you elaborate and tell us something more about the proxy setup? Like what kind of proxy is it? Does it use a PAC file?

Comment 2

[James]

Hello Daniel, 

Thank you for taking a look at this!

So admittedly my understanding of how FireFox is determining what/if any proxy to leverage is more than a bit thin. However on the same workstation with Internet Explorer / Chrome also set to 'Automatically Detect Proxy Settings' they do not experience the same degradation of performance. 

From my understanding Firefox leverages LLMNR look ups for wpad to determine if there is a Proxy in place. Looking at WireShark for a simple Google search I see that there is a request made, then a re transmission of this request half a second later. For my simple google search there appear to be 28 WPAD look ups (including both A and AAAA). This seems a bit excessive and shouldn't this detection only happen once? 

Also it seems that re-transmission happens for all of the WPAD requests. 

Is this expected behavior? I would expect Firefox to perform these LLMNR look-ups when it starts, but I wasn't expecting them to be triggered for every single domain leveraged. Which becomes more expensive with sites such as Youtube which use a million subdomains for handling video traffic.

Comment 3

[Junior [inactive]]

ni? for comment 2

Comment 4

[Daniel Stenberg [:bagder]]

Polly, any comment/help on the WPAD magic involved here?

Comment 5

[polly.shaw]

I have followed the OP's steps to investigate with Wireshark and have confirmed that Beta and Nightly repeat DNS look-ups for WPAD much more frequently than FF62 does. Both produced 16 DNS requests on a initial load of Google, but on a page refresh, FF62 did not trigger any more DNS lookups until after a minute later, but Nightly triggered an additional 16 after the first and subsequent refreshes. Both had the following prefs:
 
network.proxy.autoconfig_retry_interval_max = 300
network.proxy.autoconfig_retry_interval_min = 5

Setting the network.proxy.enable_wpad_over_dhcp pref to false on Nightly did not change this behaviour, which suggests it would also manifest itself on other platforms (DHCP lookup only being supported on Windows at the moment.)

I have done the above on a network without a proxy or a PAC file which can be found by WPAD, as I assume the OP was doing this, as setting the pref to No Proxy fixed this.

My first line of investigation is going to be mScheduledReload in nsPACMan.

Comment 6

[polly.shaw]

Checking the 'proxy' logs shows that in Nightly the back-off for retrying WPAD is no longer working - the only messages on WPAD failure are `2018-10-14 22:59:00.126000 UTC - [28736:Main Thread]: D/proxy OnLoadFailure: retry in 5 seconds (1 fails)`, while on FF62 there are exponential back-off messages such as `2018-10-14 22:59:47.416000 UTC - [28736:Main Thread]: D/proxy OnLoadFailure: retry in 20 seconds (3 fails)`

Comment 7

[polly.shaw]

Have confirmed that the functionality for exponential back-off was broken by my fix for Bug 356831, and have created a patch to fix this, currently testing on Treeherder at https://treeherder.mozilla.org/#/jobs?repo=try&revision=4245ea2d42ba8321d4245bcbc4734a30975d71ea.

Comment 8

[polly.shaw]

Attachment: Bug 1495024 - Firefox does not use exponential back-off after failing to load a PAC file.

This patch addresses a bug introduced in the solution to Bug 356831, in which
the back-off time for reloading PAC files was set to the shortest interval every time a failure happened, thus auto-detecting PAC every 5 seconds
on a network on which WPAD did not resolve when the proxy was set to auto-detect.
The changes in this patch are:
 * nsPACMan.h - declares a private overload to LoadPACFromURI, with an
 additional parameter called aResetLoadFailureCount.
 * nsPACMan.cpp - moves the implementation of the old LoadPACFromURI to the new
 private overload, with the modification that the mLoadFailureCount field
 is only reset to 0 if aResetLoadFailureCount is true. Replaces the
 implementation of the public LoadPACFromURI with a call to the private overload
 with aResetLoadFailureCount = true. Also replaces the call made from within
 nsPACMan when triggering an internal reload with a call with
 aResetLoadFailureCount = false, thus ensuring that internally triggered reloads
 do not reset the back-off time.

Comment 9

[polly.shaw]

Thanks for the review! I'm afraid I don't have permission to land this myself.

Comment 10

[Daniel Stenberg [:bagder]]

I clicked the button! =)

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ab0725fa9dc1
Firefox does not use exponential back-off after failing to load a PAC file. r=bagder

Comment 12

[Daniel Varga [:dvarga]]

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

Comment 13

[Emanuel Hoogeveen [:ehoogeveen]]

From what I understand this is a regression in Firefox 63. Seems like a simple fix for a potentially bad performance regression on certain configurations, should we uplift? (optimistically requesting tracking)

Comment 14

[Pascal Chevrel:pascalc]

We ship 63 tomorrow and the issue is not a release blocker, I am tracking the bug since it is a regression, if we have a dot release in the 63 to 64 timeframe, we will evaluate our options with regards to uplifting or not the patch.

Comment 16

[Pascal Chevrel:pascalc]

Polly, Daniel, could you request uplift to mozilla-release please? Thanks

Comment 17

[polly.shaw]

Comment on attachment 9018060 [details]
Bug 1495024 - Firefox does not use exponential back-off after failing to load a PAC file.

[Beta/Release Uplift Approval Request]

Feature/Bug causing the regression: Bug 356831

User impact if declined: Users who have proxy settings set to auto-detect and are on networks with no auto-detectable proxy will continue to experience poor performance. This has already been reported in another bug 1502404, so is serious enough for someone to have made the effort to report it

Is this code covered by automated tests?: No

Has the fix been verified in Nightly?: Yes

Needs manual test from QE?: Yes

If yes, steps to reproduce: Join network with no proxy and no auto-detectable WPAD,
    Enable logging by setting the environment variable MOZ_LOG=proxy:5,timestamp
    start Firefox
    set the Proxy type preference to Auto-detect proxy (network.proxy.type = 4)
    start browsing the web, ensuring that a new page is loaded around once every five seconds.
    search the log (which will be in stderr, unless redirected or the MOZ_LOG_FILE environment variable has been set) for proxy OnLoadFailure: retry in. Observe whether the logs show that back-off is occuring (i.e. assuming default back-off time has not been reset in preferences, first retry should be in 5 seconds; second in 10; third in 20 etc.)
    Could also see whether experience  seems particularly fast by comparison with the released Firefox, and run Wireshark filtering for dns.qry.name contains "wpad" to see whether as many requests are being made as the bug reporter said.

List of other uplifts needed: None

Risk to taking this patch: Medium

Why is the change risky/not risky? (and alternatives if risky): I have said this change is medium risk because it makes a change to the logic flow of a widely-used class. It is not high-risk because it has been tested and has been on Nightly for over a week.

String changes made/needed:

Comment 18

[Daniel Stenberg [:bagder]]

+1

Comment 21

[Pascal Chevrel:pascalc]

Comment on attachment 9018060 [details]
Bug 1495024 - Firefox does not use exponential back-off after failing to load a PAC file.

Approved for our next 63 dot release, thanks.

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-release/rev/967443c5bc7d

Comment 23

[Cristian Fogel [:cfogel]]

Would require some help with trying to reproduce/verify and some extra details regarding the issue.

What I managed to reproduce so far was to get a log file out of an affected version; but I'm not 100% yet that the "no auto-detectable WDAP" part is in order. While testing, some sub_redits where loaded slower than expected indeed.

Also, on nightly_65.0a1 (2018-11-15) the log file was generated but empty.

Comment 24

[polly.shaw]

Hi Cristi,

If you're on Windows and you have Fiddler installed, you can use it to check whether you have an auto-detectable proxy. After you connect to your network, open Fiddler -> select Tools menu -> Options item -> Gateway tab in the dialog that appears -> select 'Auto-detect proxy using WPAD'. This doesn't actually trigger an auto-detect, so restart Fiddler. Then go back to Tools-> Options-> Gateway and click the 'Show Current Gateway Info' link. If there is no auto-detectable proxy it will say 'WPAD: Not detected'.

It's surprising about the log file being empty on Nightly. nsPACMan.cpp is the only file which uses the "proxy" log module, so perhaps the preference wasn't set to auto-detect?

HTH

Polly

Comment 25

[Cristian Fogel [:cfogel]]

Hi Polly,

It did help out a bit with trying to figure things out; but there are still some things unclear to me:
- with the pref set on automatic, the message displayed is "Offline/disabled"; is this ok or it should be as you mentioned above?
- after setting the Proxy type preference to Auto-detect proxy (network.proxy.type = 4) no results seemed to be displayed in the fiddler at all, is there some other setting needed if the above mentioned item is not an issue?;
- trying to open the log file, I noticed that they're empty with the mentioned log modules;
  * attempted with same and clean profiles; 
  * appears to be carried over beta/RC/nighlty/pre_fix build;
  * here's a link for the file, if you don't mind confirming that it was with the default modules and not the requested ones: https://drive.google.com/open?id=1dIe9kgdYf_7-XGx-9OXjNKTrg8QrqwMY

Comment 26

[polly.shaw]

> with the pref set on automatic, the message displayed is "Offline/disabled"; is this ok or it should be as you mentioned above?
Yes, I think that's OK and means Fiddler can't find a proxy - in fact I have to admit that when I first opened Fiddler on a network without a detectable proxy, I got the same message as you - I only get the 'WPAD: Not detected' when I switched from a network which had a detectable proxy to one without without closing Fiddler in between.

> after setting the Proxy type preference to Auto-detect proxy (network.proxy.type = 4) no results seemed to be displayed in the fiddler at all, is there some other setting needed if the above mentioned item is not an issue?;
Yes, this is as expected; you wouldn't expect any traffic to show up in Fiddler when you get Firefox to auto-detect the proxy, because it will query the network for the proxy, rather than using the system proxy (which would be set to Fiddler, usually localhost:8888, so that Fiddler can intercept the traffic.) I suggested the use of Fiddler just to inspect your network settings rather than to intercept traffic to & from Firefox.


> trying to open the log file, I noticed that they're empty with the mentioned log modules;
  * attempted with same and clean profiles; 
  * appears to be carried over beta/RC/nighlty/pre_fix build;
  * here's a link for the file, if you don't mind confirming that it was with the default modules and not the requested ones: https://drive.google.com/open?id=1dIe9kgdYf_7-XGx-9OXjNKTrg8QrqwMY

Happy to have a look but I don't have permission to open that file. I've sent you a request through Drive itself.

Comment 27

[Cristian Fogel [:cfogel]]

Granted access to the file.

Comment 28

[Cristian Fogel [:cfogel]]

Any luck with opening the file?

Comment 29

[polly.shaw]

Hi Cristi - sorry for the delayed response. I agree that that log file doesn't seem to contain proxy output and contains the logs of several other modules, although I don't know what the default are - I thought nothing was logged by default, as it says in the link below. Maybe the environment variable isn't set correctly? In my instructions for testing I quoted the Windows way of setting the log modules, which is to omit quotes, so if you're not on Windows you may need to use quotes:

set MOZ_LOG="proxy:5,timestamp" 

https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Gecko_Logging#Enabling_Logging

Also, possibly use 'export' rather than set when setting the environment

Comment 30

[Cristian Fogel [:cfogel]]

Unfortunately I still can't get the logs to get triggered.
However while testing even in tandem with an affected build and the fixed ones, some pages again seemed to load slower(1-3+ seconds). This was the case for 63.0.3 and 64.0b11. 

Based on this, I'll mark the fix as verified.
However if anyone can still reproduce the issue please feel free to re-open the bug; I'll keep an eye out for this as well in the meanwhile. 

As for Polly, I really appreciate your help.
Keep up the good work!