1556194 - Trusted Recursive Resolver not working after notebook resume from hibernate

Status: RESOLVED FIXED

(Core :: Networking: DNS, defect, P1)

Description

[Patrick]

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

Steps to reproduce:

I had a self hosting DOH server and configure firefox to use TRR.
Having DNS problem in resolving hostnames after the notebook hibernate and resume. The problem would occurs occasionally after I used the notebook for a period without hibernate and resume.

For the DOH server side, I had tried nginx over rust-doh and PowerDNS dnsdist (embedded webserver is H2O).

Actual results:

Cannot access any website by hostname. Access by IP works.

Expected results:

It should work after the notebook resume.

Comment 1

[Kershaw Chang [:kershaw]]

Hi Patrick,

Could you help to capture the HTTP log after resuming? Please see https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging.

Thanks.

Comment 2

[Patrick]

Hi Kershaw,

Got the HTTP log after resuming, it's in here;
https://drive.google.com/file/d/1A3J29zc4JBX6mpv5re0YPkCw8Jx6qO3F/view?usp=sharing

BTW, on another occasion, just found out that the debug file of the HTTP logging may include hostname(s) of a closed private browsing sessions.

Thanks.

Comment 3

[Patrick]

For comment #2
I forget to load the CA of the DOH server. Looks like I need to capture the debug log again.
I do this on a clean machine because the original problem firefox browser connects to too many web sites (privacy concern).

Comment 4

[Kershaw Chang [:kershaw]]

(In reply to Patrick Dung from comment #3)

For comment #2
I forget to load the CA of the DOH server. Looks like I need to capture the debug log again.
I do this on a clean machine because the original problem firefox browser connects to too many web sites (privacy concern).

Thanks. You can send the log to my email (kershaw at mozilla.com) directly.

Comment 5

[Patrick]

Alright, I had send the new log to your email just now.

Comment 6

[Kershaw Chang [:kershaw]]

Well, the log shows that the TRR http channels are all canceled with the error NS_ERROR_ABORT. I can't tell the reason from the log.
Maybe FlushCache() is getting called.

Valentin, could you also take a look at the log? I've forwarded the log to you via email.

Comment 7

[Valentin Gosu [:valentin]]

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

Well, the log shows that the TRR http channels are all canceled with the error NS_ERROR_ABORT. I can't tell the reason from the log.
Maybe FlushCache() is getting called.

Valentin, could you also take a look at the log? I've forwarded the log to you via email.

I don't think FlushCache should cause the TRR channel to be cancelled. But even if it is cancelled during suspend, it should start up again and not error out.
I'll try to write some tests for this next week.

@Patrick, it's not clear from the logs. Are you using TRR in mode 2 (fallback to DNS) or mode 3 (TRR-only) ?

Comment 8

[Patrick]

I used mode 3 TRR-only.

If I use mode 2, it falled back to DNS and I did not notice problem in resolving hostnames.

Comment 9

[Ciprian.Enache]

User Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:68.0) Gecko/20100101 Firefox/68.0

This also happens on Desktop after sleep (trr.mode=3).

Comment 11

[Dmitry Sokolov]

Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:68.0) Gecko/20100101 Firefox/68.0
network.trr.mode = 3
other .trr. settings are default

FF can not load any pages after resume from the hibernation.
tcpdump shows that FF tries to connect to the 'one.one.one.one' host.
FF works as usual after re-launch or just resetting 'network.trr.mode=0'.

Also, FF sometimes stop loading pages at arbitrary moment (until re-launched or until .mode is reset).

Comment 12

[Josh Aas]

I cannot reproduce this with Firefox release in Ubuntu 19.04. Seems likely that this is Windows-only.

Comment 13

[Selena Deckelmann :selenamarie :selena]

Nhi - can you prioritize this please?

Comment 14

[Valentin Gosu [:valentin]]

(In reply to Dmitry Sokolov from comment #11)

Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:68.0) Gecko/20100101 Firefox/68.0
network.trr.mode = 3
other .trr. settings are default

FF can not load any pages after resume from the hibernation.
tcpdump shows that FF tries to connect to the 'one.one.one.one' host.
FF works as usual after re-launch or just resetting 'network.trr.mode=0'.

Also, FF sometimes stop loading pages at arbitrary moment (until re-launched or until .mode is reset).

It's not absolutely clear from the previous comments, but it would seem that both reporters run mode3 without setting a bootstrap address. When the TRR connection gets killed (such as when the computer goes to sleep), it fails to come back up because it can't resolve the domain for the DoH server anymore. This usability issue should be fixed by bug 1552176.

Comment 15

[Patrick]

Since I am self hosting the DOH server, currently I am setting a bootstrap address to my local DNS server.
I think I should have set the bootstrap address when I do the testing.

Comment 16

[Dmitry Sokolov]

but it would seem that both reporters run mode3 without setting a bootstrap address

I'm not sure, but it won't work at all, will it?

I tried 1.1.1.1, 8.8.8.8, and some other, but with mode=3 it didn't work after hibernation.

Comment 17

[Valentin Gosu [:valentin]]

(In reply to Dmitry Sokolov from comment #16)

but it would seem that both reporters run mode3 without setting a bootstrap address

I'm not sure, but it won't work at all, will it?

I tried 1.1.1.1, 8.8.8.8, and some other, but with mode=3 it didn't work after hibernation.

Could you collect some logs for me using these instructions?
https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging

You can either paste them here, or send them to me via email. Note that the logs will contain private info.

Comment 18

[Josh Aas]

I always use 1.1.1.1 for a bootstrap address with trr mode 3. On every Windows 10 machine hibernate kills the browser's ability to do DNS lookups.

I'll try to collect the logs you asked for when I get a chance.

Comment 19

[Dmitry Sokolov]

I've turned on logging. I'll post a log when the issue appears.

What kind of a private info is in a log? Cookies?

Comment 20

[Valentin Gosu [:valentin]]

(In reply to Dmitry Sokolov from comment #19)

I've turned on logging. I'll post a log when the issue appears.

What kind of a private info is in a log? Cookies?

Cookies may appear, as well as the domain names you resolve. Email is best if you're not using a clean profile.

Comment 21

[Josh Aas]

I used to be able to reproduce this easily, 100% of the time, up until at least 8 weeks ago. Now I can't reproduce.

I looked at networking bugs fixed in the last 90 days to see if there was anything that might be related to this, there are a bunch of fixes that could have impacted something like this.

Curious to hear if Dmitry or Patrick can reproduce.

Comment 22

[Dmitry Sokolov]

I've changed my config to

network.trr.bootstrapAddress = 1.1.1.1
network.trr.mode = 3

and I still can not reproduce this issue also, but my FF version now is

Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:69.0) Gecko/20100101 Firefox/69.0

and my Win10 updated recently to the build 1903 (about a month ago).

Comment 23

[Valentin Gosu [:valentin]]

I wonder if this was fixed by https://bugzilla.mozilla.org/show_bug.cgi?id=1558495#c5
It's not closed yet, but the code is on release.

Comment 24

[Patrick]

On my brief testing just now on Firefox 69.0.3, the problem seems resolved.
I would be using the 'trr mode = 3' for more testing.

Comment 25

[Valentin Gosu [:valentin]]

I'm happy to hear this works for everyone. If anyone can reproduce this again, please reopen the bug.

Comment 26

[Dmitry Sokolov]

Reproduced.
Sent email with logs to valentin....com.

Comment 27

[Nhi Nguyen (:nhi)]

Kershaw, could you take a look at the logs and see if we need to reopen the bugs? Logs forwarded via email.

Comment 28

[Kershaw Chang [:kershaw]]

(In reply to Nhi Nguyen (:nhi) from comment #27)

Kershaw, could you take a look at the logs and see if we need to reopen the bugs? Logs forwarded via email.

I think we should reopen this bug.
According to the log, TRR channels are all canceled due to timeout. Note that the timeout is only 1500ms, which seems too short for mode 3. The default timeout for mode 3 is 30000ms.

2019-10-20 18:55:04.177000 UTC - [Parent 3016: Main Thread]: D/nsHttp Creating nsHttpChannel [this=00000152011DC000]
...
2019-10-20 18:55:05.676000 UTC - [Parent 3016: Main Thread]: D/nsHostResolver TRR: 0000015201174000 canceling Channel 00000152011DC040 ocsp.digicert.com 1
2019-10-20 18:55:05.676000 UTC - [Parent 3016: Main Thread]: D/nsHttp nsHttpChannel::Cancel [this=00000152011DC000 status=80004004]

I also took a look at the http connection used for TRR channel and I can't find this line nsHttpConnection::EnsureNPNComplete [this=%p] setting complete to true in the log. I only see:

2019-10-20 18:55:04.083000 UTC - [Parent 3016: Socket Thread]: E/nsHttp nsHttpConnection::EnsureNPNComplete 0000015203B77000 - early selected alpn not available, we will try one more time.
2019-10-20 18:55:04.098000 UTC - [Parent 3016: Socket Thread]: E/nsHttp nsHttpConnection::EnsureNPNComplete 0000015203B77000 - early selected alpn not available

So, it looks like the TLS handshake is never completed or completed too late after 1500ms.

I also noticed that every OCSP request is failed because of NS_ERROR_UNKNOWN_HOST.
Maybe it's a deadlock that TLS handshake is waiting for OCSP requets and OCSP request is waiting for the TRR channel to be ready.

Valentin, what do you think?

Comment 29

[Valentin Gosu [:valentin]]

Thanks for looking into this. I think you may be on to something here.

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

According to the log, TRR channels are all canceled due to timeout. Note that the timeout is only 1500ms, which seems too short for mode 3. The default timeout for mode 3 is 30000ms.

bug 1575780 landed in Firefox 70. The logs have the UA string for Firefox 69.

So, it looks like the TLS handshake is never completed or completed too late after 1500ms.

I also noticed that every OCSP request is failed because of NS_ERROR_UNKNOWN_HOST.
Maybe it's a deadlock that TLS handshake is waiting for OCSP requets and OCSP request is waiting for the TRR channel to be ready.

Valentin, what do you think?

Ouch! That is likely to be the problem.

Comment 30

[Valentin Gosu [:valentin]]

The OCSP channel is created here

There doesn't seem to be an easy fix to this.
Until bug 1552176 lands, we can't easily except it from TRR when using mode3.

Comment 31

[Josh Aas]

I said before that I couldn't reproduce this any more, but now I can reproduce again. And it doesn't require putting the machine to sleep any more. Symptoms are consistent with the discussion happening here about timeouts.

Comment 32

[Valentin Gosu [:valentin]]

I tried reproducing this manually by pasting this into the Multiprocess Browser Console

Cc["@mozilla.org/security/x509certdb;1"].getService(Ci.nsIX509CertDB).clearOCSPCache();
Cc["@mozilla.org/network/dns-service;1"].getService(Ci.nsIDNSService).clearCache(true);

It should clear the OCSP cache and the DNS cache, but I still manage to load pages afterwards. Maybe there's another cache I also need to clear?

Patrick, does this bug still reproduce for you?

Comment 33

[Patrick]

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

Patrick, does this bug still reproduce for you?

I presume yes. I was using trr mode 2.
I would set to trr mode 3 and see if the problem is still there.

I would update about result of the testing later.

Comment 34

[Patrick]

I had tested it for a few times today and doesn't seem to reproduce the problem again.

Comment 35

[Valentin Gosu [:valentin]]

Glad to hear that. Please reopen if it starts happening again.

Comment 36

[22f270b9-4713-4981-880d-eaf31fb1ce76]

This is now broken for me using 82.0 on Arch Linux. It was working before but started happening recently, perhaps in Firefox 81? I'm not 100% sure.

Steps to reproduce:

1. Create a brand new Firefox profile
2. Set the following preferences
   security.OCSP.enabled=1 (is default value)
   security.OCSP.require=true
   network.trr.mode=3
3. Restart Firefox. This bug only occurs when security.OCSP.require=true and network.trr.mode=3 are set before Firefox launches. I assume that clearing the OCSP cache would have the same effect, but I couldn't get the console command mentioned above to work.

I can work around this bug by setting security.OCSP.require to false upon startup, and then changing it back to true, but this is incredibly annoying.

Comment 37

[Valentin Gosu [:valentin]]

Attachment: Bug 1556194 - Prevent OCSP Request from blocking TRR-only DNS resolutions r=#necko

Comment 38

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/11bb14ea6054
Prevent OCSP Request from blocking TRR-only DNS resolutions r=necko-reviewers,dragana

Comment 39

[Razvan Maries]

https://hg.mozilla.org/mozilla-central/rev/11bb14ea6054

Comment 40

[Ciprian Georgiu, Desktop QA]

Valentin, it seems that this issue is reproducing for me on FF 84 (20201207203640). I've followed the steps from comment 36, and when I access any webpage by its hostname, I'm getting this message in Firefox: Hmm. We’re having trouble finding that site. We can’t connect to the server at www.google.com.

Any ideas about what is going on here?

Comment 41

[Valentin Gosu [:valentin]]

Hi Ciprian, can you open a new bug and post the HTTP logs recorded when reproducing?
https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging
Thanks!

Comment 42

[Ciprian Georgiu, Desktop QA]

Hi Valentin! Sure, I have filled bug 1681683. Thanks.