Last Comment Bug 420187 - hang in nsNSSHttpRequestSession::internal_send_receive_attempt
: hang in nsNSSHttpRequestSession::internal_send_receive_attempt
Status: RESOLVED FIXED
: hang, relnote
Product: Core
Classification: Components
Component: Security: PSM (show other bugs)
: Trunk
: All All
P2 major (vote)
: mozilla1.9
Assigned To: Kai Engert (:kaie)
:
: David Keeler [:keeler] (use needinfo?)
Mentors:
: 408873 421757 (view as bug list)
Depends on:
Blocks: 424901 429110
  Show dependency treegraph
 
Reported: 2008-02-28 14:39 PST by Nick Thomas [:nthomas]
Modified: 2010-12-17 06:57 PST (History)
26 users (show)
shaver: blocking1.9+
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
Stacks from "hung" firefox (14.38 KB, text/plain)
2008-03-06 05:16 PST, Nick Thomas [:nthomas]
no flags Details
[checked in] Temporarily increase the time the browser stays open to 10s (491 bytes, patch)
2008-03-15 04:40 PDT, Nick Thomas [:nthomas]
sayrer: review+
ted: review+
mbeltzner: approval1.9+
Details | Diff | Splinter Review
Patch v1 (18.41 KB, patch)
2008-03-20 13:09 PDT, Kai Engert (:kaie)
no flags Details | Diff | Splinter Review
Patch v2 (18.41 KB, patch)
2008-03-20 15:02 PDT, Kai Engert (:kaie)
no flags Details | Diff | Splinter Review
another hang (15.93 KB, text/plain)
2008-03-20 17:38 PDT, Kai Engert (:kaie)
no flags Details
yet another hang (10.46 KB, text/plain)
2008-03-20 17:41 PDT, Kai Engert (:kaie)
no flags Details
Patch v3 (29.17 KB, patch)
2008-03-20 17:53 PDT, Kai Engert (:kaie)
rrelyea: review+
mbeltzner: approval1.9b5+
Details | Diff | Splinter Review
fix red tinderbox on windows (822 bytes, patch)
2008-03-25 13:05 PDT, Kai Engert (:kaie)
mtschrep: approval1.9b5+
Details | Diff | Splinter Review
fix leaks, v5 (7.96 KB, patch)
2008-03-25 14:32 PDT, Kai Engert (:kaie)
rrelyea: review+
Details | Diff | Splinter Review
screenshot (80.92 KB, image/jpeg)
2008-03-25 19:53 PDT, Carsten Book [:Tomcat]
no flags Details
regression culprit (4.58 KB, patch)
2008-03-25 20:39 PDT, Kai Engert (:kaie)
no flags Details | Diff | Splinter Review
unexpected stack (8.92 KB, text/plain)
2008-03-25 20:43 PDT, Kai Engert (:kaie)
no flags Details
Patch v7 (56.36 KB, patch)
2008-04-10 21:16 PDT, Kai Engert (:kaie)
no flags Details | Diff | Splinter Review
Patch v8 (57.33 KB, patch)
2008-04-11 16:22 PDT, Kai Engert (:kaie)
kaie: review+
Details | Diff | Splinter Review
Patch v9 (57.44 KB, patch)
2008-04-11 16:34 PDT, Kai Engert (:kaie)
kaie: review+
mbeltzner: approval1.9+
Details | Diff | Splinter Review

Description User image Nick Thomas [:nthomas] 2008-02-28 14:39:05 PST
On investigating fx-win32-tbox after 3hrs 30min building, it was stuck at:
 OBJDIR=obj-fx-trunk python obj-fx-trunk/_profile/pgo/profileserver.py

firefox.exe was in process list but not on the taskbar. When I ended the firefox process, the output was:

Application pid: 7328
FAIL Exited with code 1 during test run
fx-win32-tbox.build.mozilla.org - - [28/Feb/2008 11:33:33] "GET /index.html HTTP/1.1" 200 - fx-win32-tbox.build.mozilla.org - - [28/Feb/2008 11:33:33] "GET /quit.js HTTP/1.1" 200 -
fx-win32-tbox.build.mozilla.org - - [28/Feb/2008 11:33:34] code 404, message File not found
fx-win32-tbox.build.mozilla.org - - [28/Feb/2008 11:33:34] "GET /favicon.ico HTTP/1.1" 404 -

It continued to the second build, ignoring the exit status. If the build crashes out then tinderbox should start from the beginning.
Comment 1 User image Nick Thomas [:nthomas] 2008-03-06 05:16:54 PST
Created attachment 307694 [details]
Stacks from "hung" firefox

Had this problem with profiling again today, so attached with the debugger and did Break All. This is the resulting thread table and callstacks for each thread.
Comment 2 User image Ted Mielczarek [:ted.mielczarek] 2008-03-06 05:39:20 PST
should split this into two bugs, one for the python script not exiting with failure if the browser does, and one for the actual hang (which it looks like this bug has already been morphed into).
Comment 3 User image Ted Mielczarek [:ted.mielczarek] 2008-03-06 05:46:52 PST
Filed bug 421281 on the profiling script.
Comment 4 User image Ted Mielczarek [:ted.mielczarek] 2008-03-08 12:23:36 PST
I can reproduce this 100% of the time on OS X using the profiling script, even with a vanilla libxul build.

#0  0x908d7a46 in semaphore_timedwait_signal_trap ()
#1  0x90909daf in _pthread_cond_wait ()
#2  0x90954de7 in pthread_cond_timedwait ()
#3  0x0005cd09 in pt_TimedWait (cv=0x1c1bdcc4, ml=0x1c1bdcc4, timeout=<value temporarily unavailable, due to optimizations>) at /Users/luser/build/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:280
#4  0x0005d05c in PR_WaitCondVar (cvar=0x1c1bdcc0, timeout=250) at /Users/luser/build/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:407
#5  0x0215b97a in nsNSSHttpRequestSession::internal_send_receive_attempt (this=0x1c1bd280, retryable_error=@0xb02a348c, pPollDesc=0x0, http_response_code=0xb02a35bc, http_response_content_type=0x0, http_response_headers=0x0, http_response_data=0xb02a35b0, http_response_data_len=0xb02a35b4) at /Users/luser/build/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp:406

the main thread is sitting here:
0  0x908d7a22 in semaphore_wait_trap ()
#1  0x9094fb7f in pthread_join ()
#2  0x00061eb3 in PR_JoinThread (thred=0x3203) at /Users/luser/build/mozilla/nsprpub/pr/src/pthreads/ptthread.c:594
#3  0x021578d5 in nsPSMBackgroundThread::requestExit (this=0x3203) at /Users/luser/build/mozilla/security/manager/ssl/src/nsPSMBackgroundThread.cpp:97
#4  0x0215c63c in nsNSSComponent::DoProfileChangeNetTeardown (this=0x3203) at /Users/luser/build/mozilla/security/manager/ssl/src/nsNSSComponent.cpp:2326
Comment 5 User image Ted Mielczarek [:ted.mielczarek] 2008-03-08 12:27:26 PST
Oh, I should have pasted a full stack from that first thread:
0  0x908d7a46 in semaphore_timedwait_signal_trap ()
#1  0x90909daf in _pthread_cond_wait ()
#2  0x90954de7 in pthread_cond_timedwait ()
#3  0x0005cd09 in pt_TimedWait (cv=0x1c1bdcc4, ml=0x1c1bdcc4, timeout=<value temporarily unavailable, due to optimizations>) at /Users/luser/build/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:280
#4  0x0005d05c in PR_WaitCondVar (cvar=0x1c1bdcc0, timeout=250) at /Users/luser/build/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:407
#5  0x0215b97a in nsNSSHttpRequestSession::internal_send_receive_attempt (this=0x1c1bd280, retryable_error=@0xb02a348c, pPollDesc=0x0, http_response_code=0xb02a35bc, http_response_content_type=0x0, http_response_headers=0x0, http_response_data=0xb02a35b0, http_response_data_len=0xb02a35b4) at /Users/luser/build/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp:406
#6  0x0215bbc1 in nsNSSHttpRequestSession::trySendAndReceiveFcn (this=0x1c1bd280, pPollDesc=0x0, http_response_code=0xb02a35bc, http_response_content_type=0x0, http_response_headers=0x0, http_response_data=0xb02a35b0, http_response_data_len=0xb02a35b4) at /Users/luser/build/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp:300
#7  0x00269a52 in ocsp_GetEncodedOCSPResponseFromRequest ()
#8  0x0026b339 in CERT_CheckOCSPStatus ()
#9  0x0026e4b6 in CERT_VerifyCert ()
#10 0x0026e513 in CERT_VerifyCertNow ()
#11 0x0023d482 in SSL_AuthCertificate ()
#12 0x0215a48b in AuthCertificateCallback (client_data=0x0, fd=0x1c1b85a0, checksig=-1869776314, isServer=-1869776314) at /Users/luser/build/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp:907
#13 0x0023b31e in ssl3_HandleHandshakeMessage ()
#14 0x0023ca1e in ssl3_HandleRecord ()
#15 0x0023d0b7 in ssl3_GatherCompleteHandshake ()
#16 0x0023e08c in ssl_GatherRecord1stHandshake ()
#17 0x00241fee in ssl_Do1stHandshake ()
#18 0x00242f53 in ssl_SecureSend ()
#19 0x00242fec in ssl_SecureWrite ()
#20 0x00246df4 in ssl_Write ()
#21 0x02157db1 in nsSSLThread::Run (this=0x1b51dba0) at /Users/luser/build/mozilla/security/manager/ssl/src/nsSSLThread.cpp:1029
#22 0x0006189c in _pt_root (arg=0x1b51dc60) at /Users/luser/build/mozilla/nsprpub/pr/src/pthreads/ptthread.c:221
#23 0x90908c55 in _pthread_start ()
#24 0x90908b12 in thread_start ()

looks like it's trying to do some ocsp stuff? If I had to make an uneducated guess, I would say that we hit aus looking for extension updates, and then are screwing around in SSL code when the browser wants to shutdown.
Comment 6 User image Ted Mielczarek [:ted.mielczarek] 2008-03-08 12:29:15 PST
I guess that's in Nick's stack too. This sucks, because this hangs fx-win32-tbox on occasion (usually during the nightly). I guess it could hang anyone's browser if they startup and shutdown too quickly.
Comment 7 User image Robert Helmer [:rhelmer] 2008-03-08 21:17:05 PST
*** Bug 421757 has been marked as a duplicate of this bug. ***
Comment 8 User image Nick Thomas [:nthomas] 2008-03-11 06:18:43 PDT
Hit this again today, which is painful because takes another two and a half hours to get a nightly build out.
Comment 9 User image Mike Shaver (:shaver -- probably not reading bugmail closely) 2008-03-11 11:35:38 PDT
Marking as blocking, bad effects on build infrastructure related to fast startup-shutdown, which is also a pretty common scenario during upgrade to a new Firefox (extension compat checks, EM restarts, etc.)
Comment 10 User image Mike Shaver (:shaver -- probably not reading bugmail closely) 2008-03-11 11:42:24 PDT
Once more, with actual flags.
Comment 11 User image John O'Duinn [:joduinn] (please use "needinfo?" flag) 2008-03-14 20:08:07 PDT
Gentle ping - any update on this?
Comment 12 User image Nick Thomas [:nthomas] 2008-03-15 04:40:04 PDT
Created attachment 309626 [details] [diff] [review]
[checked in] Temporarily increase the time the browser stays open to 10s

This will hopefully prevent the tinderbox hanging until this is resolved.
Comment 13 User image Ted Mielczarek [:ted.mielczarek] 2008-03-15 05:58:47 PDT
Comment on attachment 309626 [details] [diff] [review]
[checked in] Temporarily increase the time the browser stays open to 10s

worth a shot!
Comment 14 User image timeless 2008-03-17 03:01:33 PDT
http://bonsai.mozilla.org/cvsblame.cgi?file=/mozilla/security/manager/ssl/src/nsNSSCallbacks.cpp&rev=1.62&mark=112#197

perhaps:
nsHTTPDownloadEvent::Run or nsHTTPListener should register an observer for some "shutdown" message and do something when they get it.
Comment 15 User image Mike Schroepfer 2008-03-18 11:58:12 PDT
We ready to go on this?
Comment 16 User image Ted Mielczarek [:ted.mielczarek] 2008-03-18 12:01:41 PDT
Schrep: we have a workaround in place in the PGO script, but I haven't seen any progress on the actual hang.
Comment 17 User image Kai Engert (:kaie) 2008-03-18 18:29:32 PDT
I'm working on it now
Comment 18 User image Kai Engert (:kaie) 2008-03-18 18:59:50 PDT
I'm able to reproduce this quite reliably using the following approach:
- open 5 tabs
- in the tabs, load the following sites:
  https://www.paypal.com/
  https://www.verisign.com/
  https://signin.ebay.com/
  https://www.thawte.com/
  https://www.godaddy.com/
- use File/Quit
- Select "Save all tabs", and select "do not ask me next time"
- restart firefox
- after the window is up with all 5 tabs, wait about 2 seconds, then press CTRL-Q, requesting to quit without a prompt

With this approach I can reproduce a deadlock 80% of my attempts.
Comment 19 User image Kai Engert (:kaie) 2008-03-19 07:33:56 PDT
I have a patch, but it needs a bit more polishing. Working on it. ETA later today. My patch works quite reliably.
However, using the STR from comment 18 I still get an occassional deadlock, which seems to be unrelated to the SSL thread, unrelated to OCSP. Rather the deadlock is when the SSL layer attempts to proxy a call to the main thread.

This is just an update, I'll attach more details later.
Comment 20 User image Kai Engert (:kaie) 2008-03-20 13:09:27 PDT
Created attachment 310823 [details] [diff] [review]
Patch v1

This patch seems to work, I don't see hangs on exit anymore with this patch and my steps to reproduce.

I would like to invite you to test this patch with your own STR.
Thanks!
Comment 21 User image Kai Engert (:kaie) 2008-03-20 13:22:22 PDT
Could you please explain your steps to reproduce? How did you call the profile script?

On Linux, I did this, as inspired by comment 0:
  OBJDIR=obj-fire-debug obj-fire-debug/_profile/pgo/profileserver.py

Does NOT hang for me (without patch), so I'd appreciate more detailed descriptions of the STR. Thanks!
Comment 22 User image Kai Engert (:kaie) 2008-03-20 15:02:05 PDT
Created attachment 310848 [details] [diff] [review]
Patch v2

Minor improvements compared to v1.

My proposed fix isn't small, so let me explain what I learned and the changes in this patch.

The OCSP HTTP download code usually waits for completion
(nsNSSHttpRequestSession::internal_send_receive_attempt).
We need a way to leave that loop if the application is exiting.
I added nsSSLThread::exitRequested() for that purpose.

But that isn't sufficient.
I'd expect the loop to exit after 10 seconds, but it doesn't.
So, some events are not coming in on shutdown.
Or rather: The current code is unable to cancel all loads it
wants to wait for, because:

When this code got implemented initially, an incorrect assumption was made.
It has been assumed there would be only a single OCSP download at any given time,
and tracked in static variable mPendingHTTPRequest.
The assumption is wrong.

I propose to drop the global references to pending OCSP requests
and use a direct reference in each context.
That's why I changed nsCancelHTTPDownloadEvent.

That way we are able to cancel all pending loads, the event dispatcher
will hold the last reference to the events, and they will go away as soon
as the dispatcher releases them.

In order to allow us to cancel from within the "cancel event",
forwarding to the "download event" and executing the actual network 
cancellation from there, the "download event" needs a reference 
to the loadgroup.

I'm worried about a race between nsHTTPDownloadEvent::Run
and nsHTTPDownloadEvent::Cancel.
Therefore I added a lock to synchronize access to the loadgroup member.

Then I ran into assertions, telling me that loadgroup is not threadsafe.
It happened during assignment to nsCOMPtr.

Because of that I'm using a raw pointer to refer to the loadgroup.
I remember the thread ID of the creation thread, and make sure
we'll only release it if we're on the same thread again
(we should, both actions will happen on the thread that processes events).

I hope this approach is ok. I hope the loadgroup object does not get 
created on a different thread using some proxying mechanisms that I don't see.

So, after all these changes I still ran into more problems :-(

First, I got assertions "wrong thread" from I/O-Service and about
standard-url not being thread safe. This was a simply caused by PSM
accessing the string bundle on a thread the I/O service is not happy with.
The assertion happens when using the JAR-URI for the string bundle.

I think this assertion is a separate issue, but why not fix it now.
My attempt to fix is: Load a dummy string at PSM init time.
That seems to init the string bundle objects somehow, 
it avoids the assertion in my testing.
I don't know if this is a real fix, but at least it should not hurt.

Finally, one more tricky issue.

During a recent code enhancement, when we fixed an assertion about security-UI
not being thread safe, we changed the code that tracks the security state
of a document window. We added a reentrance detection for notifications to
nsIWebProgress::OnStateChange and OnLocationChange.
I had naively assumed this reentrace would never happen and I was wrong.

The security state tracking gets notified that a load is finished,
it attempts to derive the security state, part of that is doing OCSP.
When the user cancels the load of the document, then we receive stop 
notifications, while we're still waiting for its associated OCSP download.

That's a problem. The code to track the security state is complex and
not reentrant (for a single tracked window).

I propose the following workaround:
As soon as we detect reentrace for a given object, we switch that object
into an "inconsistent" state. As long as we're in that state,
we ignore any further events that would influence or update 
the security state.

As soon as the reentrance situation has finished (we receive a new
notification back in the original frame), then we'll clear the 
tracking state and reset it to insecure.

You'll find that code if you search for "inconsistency".
Comment 23 User image Kai Engert (:kaie) 2008-03-20 17:38:55 PDT
Created attachment 310879 [details]
another hang

Even with the most recent patch I still get occassional hangs!

This time the problem is with proxying of the socket's callback pointer to the main thread. I wish that wouldn't be necessary.

Look at this attachment.
You'll see that the main thread requests termination of the SSL thread, and it wants to wait for it (it really must, because of our NSS resources shutdown story).

However, the SSL thread is trying to produce an error message. Unfortunately, it wants to give nsISSLErrorListener a chance to supress error messages. That's being proxied to the main thread which, well, is busy waiting for the SSL thread.

to be continued...
Comment 24 User image Kai Engert (:kaie) 2008-03-20 17:41:55 PDT
Created attachment 310880 [details]
yet another hang

And I got one more deadlock, this time not involving the SSL thread at all.

Occassionally Necko wants to shut down on the main thread. However, on the socket transport thread, it is still trying to set up a new SSL socket.

In nsNSSSocketInfo::SetNotificationCallbacks PSM wants to obtain some information from the provided interfaceRequested. It attempts to proxy to the main thread for querying docshell, well, but the main thread is blocked.
Comment 25 User image Kai Engert (:kaie) 2008-03-20 17:53:36 PDT
Created attachment 310884 [details] [diff] [review]
Patch v3

All I said before when explaining the proposed patch is still valid.
This patch is based on v2, but has the following changes in addition:

When building a new SSL socket, when the notification-callback-object is passed to the socket, we'll now store the original un-proxied object. And we will not immediately query the docshell to derive the information we require (e.g. whether or not to do external-error-reporting (error page)). We'll postpone that until we require the information.

In addition, I added a safety check. I'm not sure if it will be helpful in all scenarios, but it can't hurt: Whenever the SSL socket requires information from the main thread, and plans to proxy a call to the main thread, it will check whether the SSL thread is about to shut down. If it is, it doesn't make any sense to proceed, and therefore the action will be omitted and we'll return with a failure.


I don't see any hangs with this patch revision, but I'll continue testing.
Please join me :-)
Comment 26 User image Ted Mielczarek [:ted.mielczarek] 2008-03-22 18:08:18 PDT
Kai: before attachment 309626 [details] [diff] [review] was checked in, this was 100% reproducible for me on mac. You may try backing that out and testing.
Comment 27 User image Kai Engert (:kaie) 2008-03-23 13:11:50 PDT
(In reply to comment #26)
> Kai: before attachment 309626 [details] [diff] [review] was checked in, this was 100% reproducible for me
> on mac. You may try backing that out and testing.

Ted:

(a) I don't know HOW you tested. Can you please describe what exactly you did to reproduce the hang?

(b) Would you be able to back out the attachment in your local tree, apply my patch, and test that?
Comment 28 User image Ted Mielczarek [:ted.mielczarek] 2008-03-24 03:46:21 PDT
Kai: just running the profiling script, like:
"OBJDIR=obj-fx-trunk python obj-fx-trunk/_profile/pgo/profileserver.py"

I'll see if I have a chance to test with the backout+your patch today.
Comment 29 User image Mike Beltzner [:beltzner, not reading bugmail] 2008-03-24 06:02:59 PDT
We're blocking on this bug: Robert (Rylea) - any ETA of review?
Comment 30 User image Mike Beltzner [:beltzner, not reading bugmail] 2008-03-25 07:03:46 PDT
Kai: is there anyone else who can review this? rrylea seems to be AFK, and we're holding Firefox 3 Beta 5 on this fix.

Alternatively: do we need to be holding Firefox 3 Beta 5 on this fix?
Comment 31 User image Mike Schroepfer 2008-03-25 09:27:00 PDT
Dcamp can you do a drive-by?
Comment 32 User image Kai Engert (:kaie) 2008-03-25 09:40:36 PDT
(In reply to comment #28)
> Kai: just running the profiling script, like:
> "OBJDIR=obj-fx-trunk python obj-fx-trunk/_profile/pgo/profileserver.py"
> 
> I'll see if I have a chance to test with the backout+your patch today.


Thanks Ted.

I backed out attachment 309626 [details] [diff] [review], and I was able to reproduce your hang using a debug build on Linux.

I applied my patch v3, attachment 310884 [details] [diff] [review], and I no longer hang.
Comment 33 User image Ted Mielczarek [:ted.mielczarek] 2008-03-25 09:48:57 PDT
We haven't hit this on fx-win32-tbox since we bumped up the timeout, so unless Kai's patch needs beta exposure for some reason, I think we can take it afterwards.
Comment 34 User image Kai Engert (:kaie) 2008-03-25 09:57:21 PDT
(In reply to comment #33)
> We haven't hit this on fx-win32-tbox since we bumped up the timeout, so unless
> Kai's patch needs beta exposure for some reason, I think we can take it
> afterwards.

I'd recommend to have beta exposure for this patch.
There are enough changes in this patch that could allow for unexpected regressions, and we'd better see them during beta testing.
Comment 35 User image Mike Schroepfer 2008-03-25 11:18:59 PDT
Kai can you suggest a different reviewer?
Comment 36 User image Robert Relyea 2008-03-25 12:10:52 PDT
Comment on attachment 310884 [details] [diff] [review]
Patch v3

r+ I've asked kaie to include some comments, since this conditions is subtle and still has some corner cases.

Most importantly there is a corner case where the security UI may not exactly reflect the pages that are loaded. This can only happen when the stop button is pushed or the application exits. Obviously the latter isn't an issue. In the former case, the UI reflects and intermediate state that the page really had while loading, so the state of a stop page is inconsistent to begin with.

The alternative is that the browser hangs.
Comment 37 User image Kai Engert (:kaie) 2008-03-25 12:16:16 PDT
(In reply to comment #35)
> Kai can you suggest a different reviewer?

I think Bob is the person who has the most up to date knowledge on this code by far.

I guess we're good now. We have just spent 50 minutes discussing the patch, and he just gave r+.

He asked me for comments only. No code changes are planned as of now.

Given the urgency, I propose to land the code now, and I'll do the comments in a follow up patch - today!
Comment 38 User image Mike Beltzner [:beltzner, not reading bugmail] 2008-03-25 12:25:12 PDT
Comment on attachment 310884 [details] [diff] [review]
Patch v3

a1.9b5=beltzner
Comment 39 User image Kai Engert (:kaie) 2008-03-25 12:35:24 PDT
Checked in.
Marking fixed.
Comment 40 User image Kai Engert (:kaie) 2008-03-25 13:05:30 PDT
Created attachment 311638 [details] [diff] [review]
fix red tinderbox on windows
Comment 41 User image Mike Schroepfer 2008-03-25 13:14:10 PDT
Comment on attachment 311638 [details] [diff] [review]
fix red tinderbox on windows

let's get the bustage fix in..
Comment 42 User image Kai Engert (:kaie) 2008-03-25 14:32:59 PDT
Created attachment 311657 [details] [diff] [review]
fix leaks, v5

sorry my patch had introduced a leak. I have a trivial new patch that should fix it. basically I forgot to manually release that pointer to the pending load in the success scneario. but it required me to move the tracked pointer to a different object
Comment 43 User image Robert Relyea 2008-03-25 14:47:17 PDT
Comment on attachment 311657 [details] [diff] [review]
fix leaks, v5

r+ rrelyea
Comment 44 User image Kai Engert (:kaie) 2008-03-25 19:02:23 PDT
I'm afraid I have to reopen the bug.
The patch causes regressions around secure UI.

For example, open firefox, visit https://certs.starfieldtech.com/images/trust_logo.gif
then set firefox to save your session.

Quit firefox, start again, so it will load that page immediately.

With the patches applied, I get a weird UI.
No security indicators at all.
Page is being reported as insecure.

With the patches reverted, I get secure indicators and even EV status.
Comment 45 User image Mike Schroepfer 2008-03-25 19:07:35 PDT
Kai/Rob - do we want to just back this out and try and address in time for 1.9RC1 or do you have a safe plan of attack?
Comment 46 User image Jim Jeffery not reading bug-mail 1/2/11 2008-03-25 19:14:54 PDT
I just download the latest hourly, and when visiting the URL I see EV (green) Larry, and yellow in the Awesome Bar.  
Close/restart Minefield - tab loads and Larry +EV and Awesome bar look OK here, am I missing something ?

Vista HP SP1 
Mozilla/5.0 (Windows; U; Windows NT 6.0; en-US; rv:1.9b5pre) Gecko/2008032517 Minefield/3.0b5pre Firefox/3.0 ID:2008032517 <-Latest Hourly
Comment 47 User image Kai Engert (:kaie) 2008-03-25 19:16:04 PDT
I am ok to back it out.

I don't have a good plan right now, besides spending more time on this and carefully testing for regressions around security UI.
Comment 48 User image Kai Engert (:kaie) 2008-03-25 19:16:35 PDT
(In reply to comment #46)
> I just download the latest hourly, and when visiting the URL I see EV (green)
> Larry, and yellow in the Awesome Bar.  
> Close/restart Minefield - tab loads and Larry +EV and Awesome bar look OK here,
> am I missing something ?

I'm using Linux, debug build. Maybe it depends on platform and/or order of events?
Comment 49 User image Jim Jeffery not reading bug-mail 1/2/11 2008-03-25 19:20:21 PDT
I see now, once you restart if the url above is active in a tab, then the EV looks OK, but once you switch tabs and back to the tab with the url then the EV collapses to a small size and 'Larry' can't be brought up... 

Comment 50 User image Kai Engert (:kaie) 2008-03-25 19:31:09 PDT
I think the regression has to do with my change to delay querying the information from the NotifiationCallbacks / DocShell.

We could back out only that portion of the patch that introduced this new delay.

This would leave in some of the hangs I saw, but I think it fixes the most serious hangs. I'll do some tests around this idea.
Comment 51 User image Johnathan Nightingale [:johnath] 2008-03-25 19:42:48 PDT
(In reply to comment #49)
> I see now, once you restart if the url above is active in a tab, then the EV
> looks OK, but once you switch tabs and back to the tab with the url then the EV
> collapses to a small size and 'Larry' can't be brought up... 

Yep, I confirm this on Mac.  It is caused by the initial patch (attachment 310884 [details] [diff] [review]), not the red-fix or the leak-fix that followed it.

If I disable OCSP checking, Larry stops becoming unresponsive (unsurprisingly, since it means this code path isn't travelled), but the EV UI still breaks since these certs are now treated as DV by design.

In no case am I seeing anything logged to the error console.
Comment 52 User image Mike Connor [:mconnor] 2008-03-25 19:47:24 PDT
At this point I think we should back out and shoot for RC1.  This doesn't seem to be hit as often in the wild as it is in our test harness, and with the workaround we can probably safely defer to RC1...
Comment 53 User image Mike Schroepfer 2008-03-25 19:50:30 PDT
Agreed with Comment 52, looking at the dates didn't this problem ship in Beta 4?

Let's back out and give Kai and Robert time to do this right...
Comment 54 User image Carsten Book [:Tomcat] 2008-03-25 19:53:18 PDT
Created attachment 311717 [details]
screenshot

now something is wrong with the EV Cert Display. The Screenshot is from a new Build with this Patch from this Bug.

When i have 2 Sites open (like starfield and british airways) and i change the tabs fast, i get for the starfield site, the starfield favicon....but the british airways text ? 

Not sure if this is also another bug.
Comment 55 User image Johnathan Nightingale [:johnath] 2008-03-25 20:15:38 PDT
Thanks for the quick response and backout Kai, now let's continue trying to figure out what's going on.  :) 

Tomcat - I suspect it's the same bug.  Both the "Green with no text when coming from http tab" and the "green with wrong text when coming from other EV tab" behaviours sound like the SSLStatus object is not getting set properly on the gBrowser.securityUI object.

I mis-spoke before when I said I was seeing nothing in the console - swapping back and forth, I do get |this._lastStatus is null| being logged from the getIdentityData() code: 

http://mxr.mozilla.org/mozilla/source/browser/base/content/browser.js#6370

Which is not logged without the patch here (i.e. when things work).  That cached value is set here:

http://mxr.mozilla.org/mozilla/source/browser/base/content/browser.js#6407

Which is called from onSecurityChange here:

http://mxr.mozilla.org/mozilla/source/browser/base/content/browser.js#4195

So the moral is, the Identity UI is still getting the *state* changes (hence the colouring on the site button), but since SSLStatus is not being updated properly, it errors out when attempting to set the UI strings, or respond to mouseclicks.

That doesn't explain the source of the error, but I've included it in case it helps the effort to trace it.
Comment 56 User image Mike Schroepfer 2008-03-25 20:21:10 PDT
Adjusting TM and priority to match this not blocking Beta5
Comment 57 User image Kai Engert (:kaie) 2008-03-25 20:39:58 PDT
Created attachment 311726 [details] [diff] [review]
regression culprit

I identified the culprit to be this subset of patch v3.

This new code is supposed to detect an indirect reentrancy. Something the security tracking code is not designed to deal with. However, using the other portions of the patch, I detected this might happen when we quit the application or cancel loading (users presses stop).

So, I had decided, it's best to detect it, and prevent our code from executing, preventing that two parallel executions of the same function (separated by several stack levels) would cause bad things to the internal state.

Now, using the new test case "load secure page as part of session restore", I see this we run into this reentrance scenario. That's bad. The current code simply assumes that all nsIWebProgress notifications for a single target come in in serial order. According to my latest understanding, this assumption is false.

If I'm right, we must either declare that a bug in docshell (or whoever sends our the web progress notifications), or we must enhance the security tracking code to become fully reentrant.
Comment 58 User image Kai Engert (:kaie) 2008-03-25 20:43:14 PDT
Created attachment 311727 [details]
unexpected stack
Comment 59 User image Johnathan Nightingale [:johnath] 2008-03-25 20:45:22 PDT
based on comment 57, it sounds like we want biesi and bz's brains in the room, too.

Comment 60 User image Boris Zbarsky [:bz] (still a bit busy) 2008-03-25 21:01:32 PDT
> The current code simply assumes that all nsIWebProgress notifications for a
> single target come in in serial order.

What do you mean by "target"?  Notifications for a single _request_ should always be serial (the latter not happening before the former return) unless the channel implementation screws up.  But notifications for different requests inside the same loadgroup are a different issue entirely.  Here you're getting an OnLocationChange with aRequest=0x9ae1090.  The PSM code calls into NSS, NSS calls into nsNSSHttpInterface::trySendAndReceiveFcn, which posts an event to do some stuff and then spins the main thread event queue if |running_on_main_thread| (which is true, in this case).  Once you're spinning the event queue, you'll get other notifications.  You'll get arbitrary script execution.  You'll get the browser shutting down in the middle of the NS_ProcessNextEvent call.  You have to deal with all of that if you're going to spin the event queue.

I think I said pretty much this when you brought this up on IRC a few days back....

Think about it this way: the way HTTP works, requests are serialized on a connection.  Which means that if all the connections to the server are already in use, the HTTP request you're making here can't possibly complete until some of the earlier requests complete.  As they proceed and complete, they will send notifications.

Ideally, we'd avoid doing this effectively-synchronous HTTP request here.  The effect that sort of thing has on the UI is very much unsalutary.  In this case, we're polling every 50 microseconds (assuming the OS can manage that sort of resolution).  Then we're doing a bunch of work (PR_IntervalNow() is pretty expensive, if nothing else).  This will pretty much peg the CPU, and might make the UI not so responsive for the 10 seconds or so it takes this request to time out (say if all the connections to the server _are_ tied up).

Is there no possible way to kick the load off, and then return to the event loop and when it finishes handle whatever it returned?  If not, that sounds like a pretty serious issue with NSS here...
Comment 61 User image Kai Engert (:kaie) 2008-03-25 21:49:56 PDT
Boris, thanks a lot for your valuable comments.
Comment 62 User image Kai Engert (:kaie) 2008-03-26 11:17:01 PDT
*** Bug 408873 has been marked as a duplicate of this bug. ***
Comment 63 User image Mike Shaver (:shaver -- probably not reading bugmail closely) 2008-03-27 18:21:37 PDT
Is this crash related to the problem here?

http://crash-stats.mozilla.com/report/index/49b8500a-fc5d-11dc-90ee-001a4bd43e5c 

Looks to me like we re-entered an event loop and then ended up re-entering NSS, which seemed to get quite upset about it at the end.

If not, we can file another!
Comment 64 User image Boris Zbarsky [:bz] (still a bit busy) 2008-03-27 20:32:46 PDT
Yeah, that looks like exactly this issue...
Comment 65 User image Tony Chung [:tchung] 2008-04-01 10:18:19 PDT
nominating for b5 relnote.  Comment 18 has good repro steps.  and it looks like this affects Bug 424901 also, which involves certain extensions.
Comment 66 User image Kai Engert (:kaie) 2008-04-10 02:36:19 PDT
This patch will require a new enhanced patch, but I'm afraid, the new patch will have even more non-trivial changes.

Furthermore, I've finally been able to work on the review/updated patch for bug 358438. This is another important non-trivial change.

To make things more funny, the patches from this patch and bug 358438 will heavily overlap.

I think we have two options:
- land bug 358438 asap and postpone the work for this one until it's done
- I start to work on a combined patch immediately

I tend to do the latter.

Comment 67 User image Kai Engert (:kaie) 2008-04-10 20:33:23 PDT
I'm adding 383369 to the mix of overlapping patches. Bug 358438 now contains a patch that fixes both of them.
Comment 68 User image Kai Engert (:kaie) 2008-04-10 21:10:01 PDT
Summary.

We've learned from Boris that the current page state tracking implementation makes some false assumptions.

During the work on this patch, I realized there must be something wrong. I blamed the fact that my code is canceling stuff. But Boris tells us, what I saw is possible to happen at any time, and the regression after landing confirmed that.

The patch subset which I declared as "regression culprit" only served a single purpose: Detect that reentrancy we can't deal with, panic, and try to recover later. But because this can happen at any time, we panic too often.


So, doing the real fix will involve an enhanced implementation of event tracking. It might require that I introduce queues for incoming events, that can't be processed immediately. It might require posting events to avoid the reentrance.


Do we really have to wait for this new implementation?
We should work on it ASAP but is it necessary to postpone fixing this bug?

I think it's not necessary to wait.

We could take the attached patches, but without the "regression culprit" portion. (Because we're already living with the fact that our code happens to receive events in an order that it might not be prepared to handle. The patch does not make that worse.)
Comment 69 User image Kai Engert (:kaie) 2008-04-10 21:16:38 PDT
Created attachment 315037 [details] [diff] [review]
Patch v7

This is:
- patch v3 from this bug minus the regression culprit
- tinderbox fix from this bug
- fix leaks v5 from this bug
- the fix for bug 358438, which Honza and I worked on
- the fix for bug 383369, which is not yet reviewed

In my testing this bug fixes the hang on exit, and 358438 and 383369.

It probably does not yet fix the reported crash, but we can work on that in a separate step.

I would like to invite you to test this patch.
Comment 70 User image timeless 2008-04-10 23:53:13 PDT
+  attribute long subRequestsHighSecurity;
+  attribute long subRequestsLowSecurity;
+  attribute long subRequestsBrokenSecurity;
+  attribute long subRequestsNoSecurity;

these need comments at the very least. personally, i'd much rather these be arrays of nsIURI or something so that I could actually tell my users which requests are problematic. The current properties are misnamed - the word "count" or similar is necessary.
Comment 71 User image Kai Engert (:kaie) 2008-04-11 02:49:15 PDT
(In reply to comment #60)
> requests are serialized on a
> connection.  Which means that if all the connections to the server are already
> in use, the HTTP request you're making here can't possibly complete until some
> of the earlier requests complete.  As they proceed and complete, they will send
> notifications.

FYI, that request we are starting is not going to the same server, but to another one (we connect to A, and ask B to confirm A's cert is still ok).


> Ideally, we'd avoid doing this effectively-synchronous HTTP request here.  The
> effect that sort of thing has on the UI is very much unsalutary.

I have some good news, but first some background.


In the past, our processing of nsIWebProgressNotifications did not cause those recursive stacks.

When we introduced EV verification, I had decided that we should only test certs for EV when needed, and as of today, we only really need the EV status for the cert for the toplevel page.

I had used the simple approach: Look for the code that derives the overall security state for the toplevel page, and execute EV verification just before that. Which happened to be in the middle of event processing.

I did not think about threads and potential consequences. Because EV verification will require additional results from OCSP, it caused the stacks that got reported.


But luckily, things have changed just 2 days ago.

Because of a different issue (bug 406755) we had decided that we must execute the EV verification at an earlier point of time. We must execute it, while NSS still has all information from the SSL handshake with the server in memory.

This means, since the landing of bug 406755 attachment 314248 [details] [diff] [review], we're now executing EV verification and OCSP requests from a network thread (I assume it's the SSL thread that runs the NSS handshake callback).

The result of the verification will be attached to the SSL status of the socket/channel.

PSM's nsIWebProgress event processing will still call the same function to obtain the EV verification result, but the execution will no longer involve networking activity, it will use the cached result.


I can confirm this theory because I no longer get the recently added assertion about "unexpected parallel nsIWebProgress OnStateChange and/or OnLocationChange"! (which had inspired me to add the code described further above as the "regression culprit) (and as expected I quickly see the assertion when I back out attachment 314248 [details] [diff] [review] for testing purposes)


These new insights give me much more confidence that my most recent attachment to this bug is a good solution for now.
Comment 72 User image Kai Engert (:kaie) 2008-04-11 02:57:15 PDT
Comment on attachment 315037 [details] [diff] [review]
Patch v7

I'm requesting review on this bug.

As said before, it's a combination of patches from 3 bugs.

It's the earlier patch from this bug, minus the (now) unnecessary inconsistency handling. I consider that part already reviewed.

It contains the overlapping fix for bug 358438. That part was mostly prepared by Honza, I reviewed his patch and made adjustments. So that part has my and Honza's collabarative review, but Bob Relyea might want to have a another look.

Finally, it has the rather trivial fix from bug 383369, which still needs review from Bob, too.
Comment 73 User image Carsten Book [:Tomcat] 2008-04-11 03:52:05 PDT
(In reply to comment #69)
> Created an attachment (id=315037) [details]
> Patch v7
> I would like to invite you to test this patch.
> 

Hi,

the Patch works for me and also fix the crash/hang from bug 424901 for me - tested with :

Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-US; rv:1.9pre) Gecko/2008041112 Firefox/3.0pre ID:2008041112

and

Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9pre) Gecko/2008041111 Minefield/3.0pre
Comment 74 User image Boris Zbarsky [:bz] (still a bit busy) 2008-04-11 12:31:12 PDT
> This means, since the landing of bug 406755 attachment 314248 [details] [diff] [review], we're
> now executing EV verification and OCSP requests from a network thread

Do you mean that we're executing newChannel and such from off the main thread?  That's not really supported, and will likely cause issues...

But yeah, not doing the sync request from inside a web progress notification should be good.
Comment 75 User image Kai Engert (:kaie) 2008-04-11 15:19:13 PDT
(In reply to comment #74)
> 
> Do you mean that we're executing newChannel and such from off the main thread? 
> That's not really supported, and will likely cause issues...

We're initiating it on another thread, but we do it by sending an event to the main thread. (nsHTTPDownloadEvent, NS_DispatchToMainThread)
Comment 76 User image Boris Zbarsky [:bz] (still a bit busy) 2008-04-11 15:26:48 PDT
OK.  So as long as you're OK with other web progress notifications happening while that event is running, things are fine.
Comment 77 User image Kai Engert (:kaie) 2008-04-11 16:22:47 PDT
Created attachment 315219 [details] [diff] [review]
Patch v8

Bob Relyea now has reviewed all individual patches.
This Patch v8 brings in a small change that he proposed in bug 383369.

I'm marking this one as r=rrelyea, as it's simply a merged version of the individual patches.

I'll quickly do another update of this patch, to address timeless request to add a comment.
Comment 78 User image Kai Engert (:kaie) 2008-04-11 16:32:25 PDT
(In reply to comment #70)
> +  attribute long subRequestsHighSecurity;
> +  attribute long subRequestsLowSecurity;
> +  attribute long subRequestsBrokenSecurity;
> +  attribute long subRequestsNoSecurity;
> 
> these need comments at the very least.

Did you see the big comment just above?
The single comment describes them all, however, ...

> The current properties are misnamed - the word
> "count" or similar is necessary.

I agree and have added the word "count" to their names.


> personally, i'd much rather these be
> arrays of nsIURI or something so that I could actually tell my users which
> requests are problematic. 

That's a good idea, but outside of the scope of these bug fix.

Also note this interface is purely internal to PSM right now.

If you want to propose that more information (expensive) should be made available using additional properties, could you please file a separate enhancement bug?
Comment 79 User image Kai Engert (:kaie) 2008-04-11 16:34:06 PDT
Created attachment 315221 [details] [diff] [review]
Patch v9

Renamed the interface attributes as described in the previous comment, carrying forward r+
Comment 80 User image Kai Engert (:kaie) 2008-04-11 16:35:59 PDT
Comment on attachment 315221 [details] [diff] [review]
Patch v9

Requesting approval.

This bug has blocking1.9
This patch fixes this bug, and incorporates the overlapping fixes from bug 383369 (wanted-next+, wanted1.8.1.x) and bug 358438 (wanted1.9.0.x+, wanted1.8.1.x)
Comment 81 User image Mike Beltzner [:beltzner, not reading bugmail] 2008-04-11 21:24:52 PDT
Comment on attachment 315221 [details] [diff] [review]
Patch v9

a1.9=beltzner
Comment 82 User image Kai Engert (:kaie) 2008-04-11 21:39:59 PDT
Comment on attachment 309626 [details] [diff] [review]
[checked in] Temporarily increase the time the browser stays open to 10s

Do you want me to undo this timeout increase, so we can better test whether the hang fix works?
Comment 83 User image Kai Engert (:kaie) 2008-04-11 21:53:23 PDT
Patch v9 checked in, marking fixed.
Comment 84 User image Mike Beltzner [:beltzner, not reading bugmail] 2008-04-12 11:48:41 PDT
Comment on attachment 309626 [details] [diff] [review]
[checked in] Temporarily increase the time the browser stays open to 10s

Yes, please take this out, but only do it when someone's watching the tree.
Comment 85 User image Carsten Book [:Tomcat] 2008-04-12 17:30:29 PDT
Hi Kai, i can confirm that the Patch fix the Problem from Bug 424901.

During the Tests for Verification of this Bug with your steps to reproduce from comment #18 i crashed on Debug Builds and Official Windows Nightly Builds. Not sure if this crashes related to this bug, so i filed a new Bug.

I filed Bug 428716 (for the Assertion i got before the crash) and  Bug 428726 for the crash. 
Comment 86 User image Kai Engert (:kaie) 2008-04-12 20:10:05 PDT
I didn't get that assertion.

I saw the crash from bug 428726, and another crash with a different stack, see new bug 428746.

I don't know what caused those crashes, no idea whether it's a regression from this bug. It could be memory corruption.

Finally, very rarely, I still get a deadlock. It's one of the scenarios I had attempted to unblock, but it's not yet eliminated completely. We can attempt to fix that in a follow up patch. I've filed bug 428749.
Comment 87 User image timeless 2008-04-16 06:35:36 PDT
comments should really be per attribute. i don't know of *any* interfaces where attributes are just referenced by the interface comment. in general for constants there may be a comment before the first constant (not interface), but this is actually a bug, because it breaks javadoc and friends.

therefor should probably be therefore.

and i'd rather not have to file the bugs.

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