FPN proxy error often prevents Firefox from loading any pages after waking laptop

[cpeterso]

When I woke my laptop today, Firefox couldn't load any pages. I would just get a FPN proxy error page when trying to opening new tabs or reload existing tabs. I disabled and re-enabled FPN using the toolbar button and then I could load pages again.

This looks a lot issues #569 or #602, which was fixed in v11 but the related DoH bug https://bugzilla.mozilla.org/show_bug.cgi?id=1556194 was recently reopened.

I'm testing FPN v14, but I've seen this same problem for a couple months, including version v13 (October) and v11 (September). I've seen this problem intermittently on Windows 10 and macOS 10.15 Catalina, so perhaps the problem is related to my home network? This problem is common enough that I'll stop testing FPN for a couple weeks and try again, but then the problem recurs.

Here is an excerpt from an about:networking log (from version 13 in October): FPN_log.txt-main.5592.moz_log.txt. Sorry I don't have a more recent log.

[bakulf]

@mayhemer can you take a look at this log? Thanks.

[cpeterso]

I also often see problems with session restore. My session has multiple browser windows and restarting (e.g. after a Nightly update) will intermittently fail to reload the foreground tab in either the foreground window or all windows. Manually clicking the reload button will successfully load the page. So this seems like a startup race condition between session restore and FPN initialization.

Does this sound like a different bug? Should I file a separate issue? Issue #388 was filed on my behalf when I reported this session restore problem on Slack (on 2019-08-09). It was closed as a duplicate of #357, which was fixed on 2019-08-14 but I still see this problem (even today).

[cpeterso]

I reproduced this problem again today using FPN v15 and I captured an about:networking log. The log file was over 100 MB, so I had to compress it to attach it to this GitHub issue:

fpn-proxy-error-log.txt-main.18840.moz_log.txt.zip

I checked the browser console for related errors. Before I started about:networking logging, I saw these errors:

Refreshing device list failed. 
Exception { name: "NS_ERROR_NET_TIMEOUT", message: "Aborting due to channel inactivity.", result: 2152398862, filename: "resource://services-common/rest.js", lineNumber: 384, columnNumber: 0, data: null, stack: "abortTimeout@resource://services-common/rest.js:384:18\nnotify@resource://services-common/utils.js:175:20\n", location: XPCWrappedNative_NoHelper }
browser-sync.js:249:15

Refreshing device list failed. 
Object { error: Exception, errorString: "[Exception... \"NS_ERROR_PROXY_AUTHENTICATION_FAILED\"  nsresult: \"0x804b0197 (NS_ERROR_PROXY_AUTHENTICATION_FAILED)\"  location: \"JS frame :: resource://services-common/rest.js :: onStopRequest :: line 488\"  data: no]", message: null, code: null, errno: null, toString: toString() }
browser-sync.js:249:15

After I started logging and tried to load a new page, I saw many nsIInterfaceRequestor.getInterface errors:

NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIInterfaceRequestor.getInterface] 6 network-response-listener.js:84
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIInterfaceRequestor.getInterface] network-response-listener.js:84
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIInterfaceRequestor.getInterface] network-response-listener.js:84

[mayhemer]

I reproduced this problem again today using FPN v15 and I captured an about:networking log. The log file was over 100 KB, so I had to compress it to attach it to this GitHub issue:

fpn-proxy-error-log.txt-main.18840.moz_log.txt.zip

Thanks for this! Despite probably won't help to figure this one out, it's the right course of action when a problem like this is encountered.

I checked the browser console for related errors. Before I started about:networking logging, I saw these errors:

Refreshing device list failed. 
Exception { name: "NS_ERROR_NET_TIMEOUT", message: "Aborting due to channel inactivity.", result: 2152398862, filename: "resource://services-common/rest.js", lineNumber: 384, columnNumber: 0, data: null, stack: "abortTimeout@resource://services-common/rest.js:384:18\nnotify@resource://services-common/utils.js:175:20\n", location: XPCWrappedNative_NoHelper }
browser-sync.js:249:15

Refreshing device list failed. 
Object { error: Exception, errorString: "[Exception... \"NS_ERROR_PROXY_AUTHENTICATION_FAILED\"  nsresult: \"0x804b0197 (NS_ERROR_PROXY_AUTHENTICATION_FAILED)\"  location: \"JS frame :: resource://services-common/rest.js :: onStopRequest :: line 488\"  data: no]", message: null, code: null, errno: null, toString: toString() }
browser-sync.js:249:15

Yes, all the requests in the log fail with that error...

After I started logging and tried to load a new page, I saw many nsIInterfaceRequestor.getInterface errors:

NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIInterfaceRequestor.getInterface] 6 network-response-listener.js:84
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIInterfaceRequestor.getInterface] network-response-listener.js:84
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIInterfaceRequestor.getInterface] network-response-listener.js:84

This is just devtools (maybe worth filing a mozilla bug for this?)

To conclude this - it's hard to say what has happened. It looks like after the wake-up we are in the stage of refreshing auth tokens with FxA but before we are done we allow the proxy assignment callback to resolve - i.e. not wait for the refresh to finish first - which makes us use the old, expired token.

May be a motivation for #736, but maybe this can have a simpler solution.

@cpeterso, if you can, BEFORE YOU PUT YOUR LAPTOP TO SLEEP AGAIN, please install the secure-proxy/management-src at master · mozilla/secure-proxy as a temp addon and enable logging. All done in about:debugging, then you will find FPN logs there as well.

Thanks.

[cpeterso]

@cpeterso, if you can, BEFORE YOU PUT YOUR LAPTOP TO SLEEP AGAIN, please install the secure-proxy/management-src at master · mozilla/secure-proxy as a temp addon and enable logging. All done in about:debugging, then you will find FPN logs there as well.

I've installed the temp add-on. Where can I find the FPN logs? I don't see any log data or file names on the add-on's Management interface page.

[cpeterso]

I reproduced the page loading problem this morning with the Management interface extension installed. Unfortunately, I didn't see any relevant error messages in the Management interface's Toolbox log (opened from about:debugging's "Inspect" button).

If there's anything else you'd like me to try testing, just let me know. I can reproduce this FPN error nearly every morning.

The problem rarely happens during the day (e.g. when my computer is sleeping during my lunch). So perhaps the problem depends on the duration my computer is sleeping? I see this problem on both my MacBook Pro and Windows 10 laptop (but much more on Windows), so it doesn't seem related to any OS-specific network condition during sleep or Windows auto-restarting to apply OS updates in the middle of the night.

[cpeterso]

I still see this problem nearly every day (on Windows and macOS). It also blocks Firefox checking for Nightly updates, not just web page loading. I'm currently using FPN v15.

[cpeterso]

I still see this problem nearly every day on Windows and macOS. I'm now using FPN v17. I assume there must be something unusual about my home LAN setup.

[cpeterso]

@mayhemer - I can still reproduce this problem with FPN extension v22. FPN is unusable for me.

@cpeterso, if you can, BEFORE YOU PUT YOUR LAPTOP TO SLEEP AGAIN, please install the secure-proxy/management-src at master · mozilla/secure-proxy as a temp addon and enable logging. All done in about:debugging, then you will find FPN logs there as well.

You said above that the management-src extension's logs should appear in about:debugging, but I don't see any references to logs there.

[ValentinaPC]

Please take a look over: #899 . Thanks!

[cpeterso]

I think my problem is different. I'm in the US and Secure Proxy works fine until I sleep my laptop.

[ValentinaPC]

I think my problem is different. I'm in the US and Secure Proxy works fine until I sleep my laptop.

I think is has the same root cause. I am able to reproduce "my" issue in US also, as you can see in the video. I may be wrong.

[cpeterso]

I can still reproduce this problem with FPN extension v23. When I restart Firefox with FPN enabled, session restore often fails to reload my pinned tabs or the focused tab in each of my browser windows.

[cpeterso]

I can still reproduce the "foreground tab and pinned tabs fail to load during session restore" variant of this bug with FPN extension v24 and Firefox Nightly 85.

When restarting Nightly, the foreground tab and pinned tabs in every browser window frequently fail to load during session restore. Manually clicking the reload button will successfully load the page. This seems like a startup race condition between session restore and FPN initialization.