914034 - After exiting browser, The process of Firefox stays for a extremely long time

Status: VERIFIED FIXED

(Core :: Security: PSM, defect)

Description

[Alice0775 White]

Build Identifier:
http://hg.mozilla.org/mozilla-central/rev/4ca898d7db5f
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:26.0) Gecko/20100101 Firefox/26.0 ID:20130908030205

This problem happens in Aurora25.0a2 and Nightly26.0a1 but not in Firefox24.0b9.


Steps To Reproduce:
1. Start Firefox with clean profile
2. Middle click "Mozilla Firefox" folder in Bookmarks to open all in tabs
3. Close Firefox immediately after "Middle click" of step 2.

Actual Results:
The process of Firefox stays for a long time (10-15sec)

Expected Results:
The process of Firefox should disappear within (1-3sec)

Comment 1

[Alice0775 White]

Regression window(m-i)
Good:
http://hg.mozilla.org/integration/mozilla-inbound/rev/0fd96a1e096b
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20130624 Firefox/24.0 ID:20130624075801
Bad:
http://hg.mozilla.org/integration/mozilla-inbound/rev/923aca74a801
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20130624 Firefox/24.0 ID:20130624091504
Pushlog:
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=0fd96a1e096b&tochange=923aca74a801

Suspected:
98cfdd66fe87	David Keeler — bug 700693 - OCSP stapling PSM changes r=bsmith

And if security.ssl.enable_ocsp_stapling = false, This problem does not seem to happen

Comment 2

[Alice0775 White]

Attachment: WinDbg log, break just after close brower(while the process is running)

Comment 3

[Alex Keybl [:akeybl]]

(In reply to Alice0775 White from comment #0)
> Build Identifier:
> http://hg.mozilla.org/mozilla-central/rev/4ca898d7db5f
> Mozilla/5.0 (Windows NT 6.1; WOW64; rv:26.0) Gecko/20100101 Firefox/26.0
> ID:20130908030205
> 
> This problem happens in Aurora25.0a2 and Nightly26.0a1 but not in
> Firefox24.0b9.
> 
> 
> Steps To Reproduce:
> 1. Start Firefox with clean profile
> 2. Middle click "Mozilla Firefox" folder in Bookmarks to open all in tabs
> 3. Close Firefox immediately after "Middle click" of step 2.

How clickly does step 3 need to be performed? Seems like an edge case (albeit a regression).

Comment 4

[Alice0775 White]

(In reply to Alex Keybl [:akeybl] from comment #3)
> (In reply to Alice0775 White from comment #0)
> > Build Identifier:
> > http://hg.mozilla.org/mozilla-central/rev/4ca898d7db5f
> > Mozilla/5.0 (Windows NT 6.1; WOW64; rv:26.0) Gecko/20100101 Firefox/26.0
> > ID:20130908030205
> > 
> > This problem happens in Aurora25.0a2 and Nightly26.0a1 but not in
> > Firefox24.0b9.
> > 
> > 
> > Steps To Reproduce:
> > 1. Start Firefox with clean profile
> > 2. Middle click "Mozilla Firefox" folder in Bookmarks to open all in tabs
> > 3. Close Firefox immediately after "Middle click" of step 2.
> 
> How clickly does step 3 need to be performed? Seems like an edge case
> (albeit a regression).

I think it depend on the number of opening tabs.
In this case, about 1-2 sec(while the icon of the tab is spinning)

Because when I opened unwanted Firefox by mistake.
I think this is edge case.

Comment 5

[Lukas Blakk [:lsblakk] use ?needinfo]

As an edge case we wouldn't block the release on this but would look at a low risk uplift if available - David what's your read here on what might be causing this from your work in bug 700693?

Comment 6

[Dana Keeler (she/her) [:keeler]]

I haven't looked very far into this, but my best guess at the moment is a poor interaction (wrt thread blocking) between caching a stapled response and requesting a non-stapled response. Currently there's a 10-second timeout for OCSP requests that bug 918120 will be reducing to 2 seconds. If, after that lands, this delay gets shortened to a few seconds instead of 10-15, I bet that's the problem. If so, the OCSP code may need to be restructured. In the meantime, I'll keep poking around to see what I can find.

Comment 7

[Dana Keeler (she/her) [:keeler]]

Attachment: patch

Turns out, CERT_CacheOCSPResponseFromSideChannel can cause synchronous OCSP requests. This is bad news if we're running on the socket thread. (It basically just stops all network traffic for 10 seconds and then fails to cache the response.) This patch ensures that stapled OCSP responses get processed off the socket thread.
Brian - OCSP stapling is unlikely to get any traction if we don't fix this. If you can have a look within two weeks, that would be great.

Comment 8

[Brian Smith (:briansmith, :bsmith, use NEEDINFO?)]

Comment on attachment 808834 [details] [diff] [review]
patch

Review of attachment 808834 [details] [diff] [review]:
-----------------------------------------------------------------

David, I have a patch that does basically the same thing as what you've done, but which moves all the logic all the way to CertVerifier.

::: security/manager/ssl/src/SSLServerCertVerification.cpp
@@ +1050,5 @@
> +    if (mStapledOCSPResponse) {
> +      CERTCertDBHandle *handle = CERT_GetDefaultCertDB();
> +      rv = CERT_CacheOCSPResponseFromSideChannel(handle, mCert, PR_Now(),
> +                                                 mStapledOCSPResponse,
> +                                                 mInfoObject);

How about moving this call to AuthCertificate so that you don't have to duplicate this in two spots?

@@ +1237,5 @@
> +  if (stapledOCSPResponse) {
> +    CERTCertDBHandle *handle = CERT_GetDefaultCertDB();
> +    rv = CERT_CacheOCSPResponseFromSideChannel(handle, serverCert, now,
> +                                               stapledOCSPResponse,
> +                                               socketInfo);

How about moving this call to AuthCertificate so that you don't have to duplicate this in two spots?

::: security/manager/ssl/src/nsNSSCallbacks.cpp
@@ +254,5 @@
> +  nsCOMPtr<nsIEventTarget> sts
> +    = do_GetService(NS_SOCKETTRANSPORTSERVICE_CONTRACTID, &nrv);
> +  if (NS_FAILED(nrv)) {
> +    NS_ERROR("Could not get STS service");
> +    PR_SetError(PR_UNKNOWN_ERROR, 0);

Use PR_INVALID_STATE_ERROR. (also below).

@@ +266,5 @@
> +    return SECFailure;
> +  }
> +
> +  if (onSTSThread) {
> +    NS_ERROR("nsNSSHttpRequestSession::trySendAndReceiveFcn called on socket thread; this will not work.");

Wrap at 80 chars:

  NS_ERROR("....."
           "...")

Comment 9

[Dana Keeler (she/her) [:keeler]]

Attachment: patch updated

Thanks for the review. Addressing comments, carrying over r+.
The try run was looking good: https://tbpl.mozilla.org/?tree=Try&rev=e3f1980743fe so I went ahead with this on inbound: https://hg.mozilla.org/integration/mozilla-inbound/rev/a13edd3c49e7
I don't have a test yet, because this is going to require a non-trivial re-working of our ocsp stapling test infrastructure and it's important we get this fixed and uplifted quickly. I'll file a bug to follow up, though.

Comment 10

[Phil Ringnalda (:philor)]

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

Comment 11

[Camilo Viecco (:cviecco)]

keele: is this really fixed? the commit looked like OCSP stapling support.

Comment 12

[Dana Keeler (she/her) [:keeler]]

(In reply to Camilo Viecco (:cviecco) from comment #11)
> keele: is this really fixed? the commit looked like OCSP stapling support.

Right - the bug was that trying to stash an OCSP response can cause further OCSP requests (e.g. for the intermediate). If this is done on the socket transport thread, it'll end up waiting for itself to finish, which won't happen, so it'll time out after 10 seconds and fail (hence firefox waiting around for a while even after the ui was closed).

Comment 13

[Dana Keeler (she/her) [:keeler]]

D'oh - unset the milestone accidentally somehow.

Comment 14

[Dana Keeler (she/her) [:keeler]]

Comment on attachment 813341 [details] [diff] [review]
patch updated

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 700693 (OCSP stapling)
User impact if declined: OCSP stapling will not work when an intermediate certificate has OCSP information that hasn't been cached yet. Also observable as occasional 10-second delays in shutdown.
Testing completed (on m-c, etc.): landed on m-c
Risk to taking this patch (and alternatives if risky): Low
String or IDL/UUID changes made by this patch: none

Comment 15

[Alex Keybl [:akeybl]]

Comment on attachment 813341 [details] [diff] [review]
patch updated



Let's get this on Firefox 26 and later since this isn't a critical landing for beta.

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/e87c5779660a

Comment 18

[Alex Keybl [:akeybl]]

Bug 928832 has now been marked as a duplicate of this bug, so we're going to take this forward fix in our final beta. We're also seeing if this is related to bug 929063.

Comment 19

[Alex Keybl [:akeybl]]

Comment on attachment 813341 [details] [diff] [review]
patch updated

Keeler, RyanVM isn't around this week. Would you mind landing?

Comment 20

[Dana Keeler (she/her) [:keeler]]

https://hg.mozilla.org/releases/mozilla-beta/rev/676ed933b962

If QA could verify that this fixes bug 929063 and bug 928832, that would be great.

Comment 21

[Tracy Walker [:tracy]]

this does fix bug 929063 and bug 928832 on nightly. With an oldish Nightly, I wasn't able to reproduce the process hanging about as originally described here.  And process goen in less than 3 seconds with current nightly.

Comment 22

[Alice0775 White]

I can verify. I cannot reproduce the problem in Nightly27.0a1 and Arrora26.0a2
In Nightly27.0a1 and Arrora26.0a2, process disappears immediately after closing browser.

http://hg.mozilla.org/mozilla-central/rev/23c23b472a4f
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101 Firefox/27.0 ID:20131021030203
http://hg.mozilla.org/releases/mozilla-aurora/rev/d585fe28cd55
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:26.0) Gecko/20100101 Firefox/26.0 ID:20131021004002


However,in Firefox25.0b9, process stays for about 5-6sec.

http://hg.mozilla.org/releases/mozilla-beta/rev/18d6461ab468
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:25.0) Gecko/20100101 Firefox/25.0 ID:20131017174213

Comment 23

[Cornel Ionce [:noni] [Hubs QA]]

Mozilla/5.0 (Windows NT 6.1; WOW64; rv:25.0) Gecko/20100101 Firefox/25.0
Mozilla/5.0 (X11; Linux i686; rv:25.0) Gecko/20100101 Firefox/25.0
Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:25.0) Gecko/20100101 Firefox/25.0

Mozilla/5.0 (X11; Linux i686; rv:26.0) Gecko/20100101 Firefox/26.0
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:26.0) Gecko/20100101 Firefox/26.0
Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:26.0) Gecko/20100101 Firefox/26.0

Verified on Firefox 25 beta 10 (build ID: 20131021191948) and on latest Aurora (build ID: 20131021004002).

The process of Firefox disappear after 1-2 seconds after the browser is closed. Verified using the steps from comment 0.

Also, bug 929063 and bug 928832 were verified as requested per commented 20 on these three platforms (Windows 7x64, Mac OS X 10.7 and Ubuntu 12.04) using latest Aurora and Firefox 25 beta 10 and they are no longer reproducing.

Marking this issue as verified.