Mike Conley (:mconley) (:⚙️) Reporter
	Description • 12 years ago

On a Linux debug build of comm-central.

STR:

1. Start up Thunderbird, and open up the "What's New" tab.
2. Close Thunderbird with the "What's New" tab still open. 
3. Restart Thunderbird. The "What's New" tab should restore itself.
4. Wait a few seconds.

What happens?

Crash!

What's expected?

No crashes please.

Backtrace:

#0  0xb78ce424 in __kernel_vsyscall ()
#1  0xb7672c16 in nanosleep () at ../sysdeps/unix/syscall-template.S:82
#2  0xb7672a0f in __sleep (seconds=0) at ../sysdeps/unix/sysv/linux/sleep.c:138
#3  0xb4428669 in ah_crap_handler (signum=6) at /media/Projects/mozilla/thunderbird/mozilla/toolkit/xre/nsSigHandlers.cpp:87
#4  0xb442f07b in nsProfileLock::FatalSignalHandler (signo=6, info=0xbfb7297c, context=0xbfb729fc) at /media/Projects/mozilla/objdir-thunderbird-patches/mozilla/toolkit/profile/nsProfileLock.cpp:190
#5  <signal handler called>
#6  0xb78ce424 in __kernel_vsyscall ()
#7  0xb78a7dde in raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/pt-raise.c:42
#8  0xb45005fe in mozilla::net::nsHttpChannel::ReadFromCache (this=0x9f116c00, alreadyMarkedValid=false) at /media/Projects/mozilla/thunderbird/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:3450
#9  0xb4501538 in mozilla::net::nsHttpChannel::ProcessNotModified (this=0x9f116c00) at /media/Projects/mozilla/thunderbird/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:2186
#10 0xb450475a in mozilla::net::nsHttpChannel::ProcessResponse (this=0x9f116c00) at /media/Projects/mozilla/thunderbird/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:1250
#11 0xb4504b46 in mozilla::net::nsHttpChannel::OnStartRequest (this=0x9f116c00, request=0x9f13e640, ctxt=0x0) at /media/Projects/mozilla/thunderbird/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:4747
#12 0xb4451e15 in nsInputStreamPump::OnStateStart (this=0x9f13e640) at /media/Projects/mozilla/thunderbird/mozilla/netwerk/base/src/nsInputStreamPump.cpp:416
#13 0xb4452568 in nsInputStreamPump::OnInputStreamReady (this=0x9f13e640, stream=0x9f19853c) at /media/Projects/mozilla/thunderbird/mozilla/netwerk/base/src/nsInputStreamPump.cpp:367
#14 0xb55fd8eb in nsInputStreamReadyEvent::Run (this=0x9f13f680) at /media/Projects/mozilla/thunderbird/mozilla/xpcom/io/nsStreamUtils.cpp:81
#15 0xb56125f7 in nsThread::ProcessNextEvent (this=0xb734cf20, mayWait=true, result=0xbfb730bf) at /media/Projects/mozilla/thunderbird/mozilla/xpcom/threads/nsThread.cpp:624
#16 0xb55ceec8 in NS_ProcessNextEvent_P (thread=<optimized out>, mayWait=true) at /media/Projects/mozilla/objdir-thunderbird-patches/mozilla/xpcom/build/nsThreadUtils.cpp:213
#17 0xb54f37b4 in mozilla::ipc::MessagePump::Run (this=0xb2619490, aDelegate=0xb735b900) at /media/Projects/mozilla/thunderbird/mozilla/ipc/glue/MessagePump.cpp:113
#18 0xb563fddc in MessageLoop::RunInternal (this=0xb735b900) at /media/Projects/mozilla/thunderbird/mozilla/ipc/chromium/src/base/message_loop.cc:208
#19 0xb563fe01 in RunHandler (this=0xb735b900) at /media/Projects/mozilla/thunderbird/mozilla/ipc/chromium/src/base/message_loop.cc:201
#20 MessageLoop::Run (this=0xb735b900) at /media/Projects/mozilla/thunderbird/mozilla/ipc/chromium/src/base/message_loop.cc:175
#21 0xb50fd715 in nsBaseAppShell::Run (this=0xb12512e0) at /media/Projects/mozilla/thunderbird/mozilla/widget/xpwidgets/nsBaseAppShell.cpp:163
#22 0xb4f42a74 in nsAppStartup::Run (this=0xb1278130) at /media/Projects/mozilla/thunderbird/mozilla/toolkit/components/startup/nsAppStartup.cpp:256
#23 0xb4423298 in XREMain::XRE_mainRun (this=0xbfb733e0) at /media/Projects/mozilla/thunderbird/mozilla/toolkit/xre/nsAppRunner.cpp:3786
#24 0xb4423546 in XREMain::XRE_main (this=0xbfb733e0, argc=1, argv=0xbfb746a4, aAppData=0xb73158c0) at /media/Projects/mozilla/thunderbird/mozilla/toolkit/xre/nsAppRunner.cpp:3863
#25 0xb44237ad in XRE_main (argc=1, argv=0xbfb746a4, aAppData=0xb73158c0, aFlags=0) at /media/Projects/mozilla/thunderbird/mozilla/toolkit/xre/nsAppRunner.cpp:3939
#26 0x0804a0ee in do_main (argv=0xbfb746a4, argc=1, exePath=0xbfb735dc "/media/Projects/mozilla/objdir-thunderbird-patches/mozilla/dist/bin/") at /media/Projects/mozilla/thunderbird/mail/app/nsMailApp.cpp:111
#27 main (argc=<error reading variable: Cannot access memory at address 0x6c9>, argv=<error reading variable: Cannot access memory at address 0x6cd>) at /media/Projects/mozilla/thunderbird/mail/app/nsMailApp.cpp:200

	David :Bienvenu
	Comment 1 • 12 years ago

I see this on windows as well.

	Mike Conley (:mconley) (:⚙️) Reporter
	Comment 2 • 12 years ago

This assertion that we're failing seems to have been introduced via bug 746018.

	:Irving Reid (No longer working on Firefox)
	Comment 3 • 12 years ago

I'm seeing it maybe 1/3 of the time on Mac

	Florian Quèze [:florian]
	Comment 4 • 12 years ago

This is how it looks in my terminal when it crashes:

Failed to load file:///Users/florian/buildhg/comm-central/obj-tbird/mozilla/dist/DailyDebug.app/Contents/MacOS/chrome/messenger/content/messenger/AccountManager.js
++DOMWINDOW == 28 (0x22deb3ec) [serial = 28] [outer = 0x1e7260f0]
WARNING: NS_ENSURE_TRUE(mScriptGlobalObject) failed: file /Users/florian/buildhg/comm-central/mozilla/content/xul/document/src/nsXULDocument.cpp, line 3598
WARNING: NS_ENSURE_TRUE((mCachedResponseHead->Status() / 100 != 3) || isCachedRedirect) failed: file /Users/florian/buildhg/comm-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp, line 2941
WARNING: cache check failed: file /Users/florian/buildhg/comm-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp, line 2857
--DOMWINDOW == 27 (0x22de992c) [serial = 27] [outer = 0x1e7260f0] [url = chrome://messenger/content/msgAccountCentral.xul]
--DOMWINDOW == 26 (0x22d9975c) [serial = 17] [outer = 0x228894d0] [url = about:blank]
--DOMWINDOW == 25 (0x22d7e4cc) [serial = 16] [outer = 0x2288f4b0] [url = about:blank]
--DOMWINDOW == 24 (0x22dd3e6c) [serial = 18] [outer = 0x1e7260f0] [url = about:blank]
Assertion failure: mCacheAsyncInputStream, at /Users/florian/buildhg/comm-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:3450


And the same part of the log when it doesn't crash:
Failed to load file:///Users/florian/buildhg/comm-central/obj-tbird/mozilla/dist/DailyDebug.app/Contents/MacOS/chrome/messenger/content/messenger/AccountManager.js
++DOMWINDOW == 28 (0x24d1beac) [serial = 28] [outer = 0x1e726060]
WARNING: NS_ENSURE_TRUE(mScriptGlobalObject) failed: file /Users/florian/buildhg/comm-central/mozilla/content/xul/document/src/nsXULDocument.cpp, line 3598
WARNING: NS_ENSURE_TRUE(mCachedResponseHead) failed: file /Users/florian/buildhg/comm-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp, line 2126
--DOMWINDOW == 27 (0x22de970c) [serial = 27] [outer = 0x1e726060] [url = chrome://messenger/content/msgAccountCentral.xul]
--DOMWINDOW == 26 (0x22d9969c) [serial = 17] [outer = 0x228894d0] [url = about:blank]
--DOMWINDOW == 25 (0x22d7e40c) [serial = 16] [outer = 0x2288f4c0] [url = about:blank]
--DOMWINDOW == 24 (0x22dd3d9c) [serial = 18] [outer = 0x1e726060] [url = about:blank]

	Florian Quèze [:florian]
	Comment 5 • 12 years ago

Note: The 2 logs in comment 4 were with -purgecaches on the command line. Without it, I see an additional assertion, immediately after the "Failed to load" message:

Failed to load file:///Users/florian/buildhg/comm-central/obj-tbird/mozilla/dist/DailyDebug.app/Contents/MacOS/chrome/messenger/content/messenger/AccountManager.js
###!!! ASSERTION: Existing entry in disk StartupCache.: 'zipItem == nsnull', file /Users/florian/buildhg/comm-central/mozilla/startupcache/StartupCache.cpp, line 344

	Florian Quèze [:florian]
	Comment 6 • 12 years ago

I've just tried with a fresh profile, and some of the messages in comment 4 and 5 don't appear.

In my terminal before the crash I see:
WARNING: NS_ENSURE_TRUE((mCachedResponseHead->Status() / 100 != 3) || isCachedRedirect) failed: file /Users/florian/buildhg/comm-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp, line 2941
WARNING: cache check failed: file /Users/florian/buildhg/comm-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp, line 2857
Assertion failure: mCacheAsyncInputStream, at /Users/florian/buildhg/comm-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp:3450


And when there's no crash I see:
WARNING: NS_ENSURE_TRUE(mCachedResponseHead) failed: file /Users/florian/buildhg/comm-central/mozilla/netwerk/protocol/http/nsHttpChannel.cpp, line 2126

	Mike Conley (:mconley) (:⚙️) Reporter
	Comment 7 • 12 years ago

I reported this yesterday before the merge, so I'm pretty sure this crash just got merged over to comm-aurora.

I'm gonna take a run at this today to see what's going on.

	Mike Conley (:mconley) (:⚙️) Reporter
	Comment 8 • 12 years ago

Having read into the patch a bit more, I'm starting to suspect that this is indeed caused by bug 746018. I'm compiling without those patches to confirm.

	Mike Conley (:mconley) (:⚙️) Reporter
	Comment 9 • 12 years ago

Yep, the patches in bug 746018 introduce the assertion, and our debug builds crash with them, and don't without them.

So either we've hit an edge case, or we're somehow abusing nsHttpChannel and need to change our ways. Either way, marking this as blocking 746018.

	Brian Smith (:briansmith, :bsmith, use NEEDINFO?) Assignee
	Comment 10 • 12 years ago

I filed the platform bug, bug 761660 to track the fixing of the platform bug that is causing this crash. Even if you are doing something unusual with nsHttpChannel, we should not be crashing.

It would very very useful to get a log of this, as I cannot reproduce. Please run Daily with NSPR_LOG_MODULES=nsHttp:5 and add the log to this bug or to bug 761660. Thanks!

	Mike Conley (:mconley) (:⚙️) Reporter
	Comment 11 • 12 years ago

(In reply to Brian Smith (:bsmith) from comment #10)
> I filed the platform bug, bug 761660 to track the fixing of the platform bug
> that is causing this crash. Even if you are doing something unusual with
> nsHttpChannel, we should not be crashing.
> 

Note that this crash is due to an assertion failure, and I think we want to crash on those - so the crash, while unpleasant, is not necessarily unexpected / unwanted.

> It would very very useful to get a log of this, as I cannot reproduce.
> Please run Daily with NSPR_LOG_MODULES=nsHttp:5 and add the log to this bug
> or to bug 761660. Thanks!

Sure, posting in bug 761660.

	Florian Quèze [:florian]
	Comment 12 • 12 years ago

(In reply to Brian Smith (:bsmith) from comment #10)

> It would very very useful to get a log of this, as I cannot reproduce.
> Please run Daily with NSPR_LOG_MODULES=nsHttp:5 and add the log to this bug
> or to bug 761660. Thanks!

The build I used to generate this log has the
MOZ_ASSERT(mCacheAsyncInputStream); line commented out so that I could
work on something else, but I added a comment in the log at the point where the crash would occur.

	Florian Quèze [:florian]
	Comment 13 • 12 years ago

Note to Thunderbird developers annoyed by this crash:

The debug log I attached shows that we crash during the HTTP request for testpilot.mozillalabs.com/testcases/index-tb.json so I think we can workaround the crash by disabling the Test Pilot add-on.

	:Irving Reid (No longer working on Firefox)
	Comment 14 • 12 years ago

(In reply to Florian Quèze from comment #13)
> Note to Thunderbird developers annoyed by this crash:
> 
> The debug log I attached shows that we crash during the HTTP request for
> testpilot.mozillalabs.com/testcases/index-tb.json so I think we can
> workaround the crash by disabling the Test Pilot add-on.

Interesting - I wonder if TP (at least under Thunderbird) is trying to initialize before all the infrastructure is set up? If so, it would be nice to get a more human-readable error message.

Is there a well defined point in the platform startup when the HTTP channel caching becomes ready to use?

	Brian Smith (:briansmith, :bsmith, use NEEDINFO?) Assignee
	Comment 15 • 12 years ago

I don't think this has to do with using the HTTP cache before it is ready to be used.

The issue seems to be related to this check failing:

   NS_ENSURE_TRUE((mCachedResponseHead->Status() / 100 != 3) || isCachedRedirect)

It looks like we wrote a 3xx response into the cache and this new stricter check I added is refusing to cache that. But, then we get a 304 response from the server and we start to read from the cache entry input stream that we didn't create.

Still haven't determined why we're sending a conditional request. I wonder if TestPilot is doing a custom conditional request; if so, the problem is probably that we do not set mCustomConditionalRequest before we do the above check.

	:Irving Reid (No longer working on Firefox)
	Comment 16 • 12 years ago

Test Pilot is trying to explicitly manage this particular file download to use a local cached version if it is unable to retrieve the on-line version; see

http://mxr.mozilla.org/comm-central/source/mail/app/profile/extensions/tbtestpilot@labs.mozilla.com/modules/remote-experiment-loader.js#448

and

http://mxr.mozilla.org/comm-central/source/mail/app/profile/extensions/tbtestpilot@labs.mozilla.com/modules/remote-experiment-loader.js#85

Copy Gregg Lind on the bug in case he can help with the specifics of the test pilot experiment loader.

	Brian Smith (:briansmith, :bsmith, use NEEDINFO?) Assignee
	Comment 17 • 12 years ago

Here is the test case. If you run it on an unpatched build, it will crash. With the upcoming patch, there is no crash and we correctly process the response.

make -C netwerk/test
SOLO_FILE=test_customConditionalRequest_304.js make -C netwerk/test check-one

	Brian Smith (:briansmith, :bsmith, use NEEDINFO?) Assignee
	Comment 18 • 12 years ago

Comment on attachment 632111 [details] [diff] [review]
test case

Will update the test case to include another case.

	Brian Smith (:briansmith, :bsmith, use NEEDINFO?) Assignee
	Comment 19 • 12 years ago

Here's the test case that can be used to reproduce the crash.

	Brian Smith (:briansmith, :bsmith, use NEEDINFO?) Assignee
	Comment 20 • 12 years ago

The bug was mainly that we returned from CheckCache() before setting mCustomConditionalRequest. This patch fixes the bug by remembering that that the request is a custom conditional request before we would ever return from CheckCache.

	Jason Duell
	Comment 22 • 12 years ago

Comment on attachment 632187 [details] [diff] [review]
test case [v2]

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

::: netwerk/test/unit/test_304_responses.js
@@ +33,5 @@
> +  response.setHeader("Returned-From-Handler", "1");
> +}
> +
> +function run_test() {
> +  evict_cache_entries();

As mentioned on IRC, we don't currently store cache entries across XPCshell tests, so no need to evict at startup.

@@ +64,5 @@
> +
> +// Test that we can cope with a 304 response that was (erroneously) stored in
> +// the cache.
> +add_test(function test_304_stored_in_cache() {
> +  asyncOpenCacheEntry(

It's really nice that we have this new ability to create cache entries in tests.  Good stuff.

	Jason Duell
	Comment 23 • 12 years ago

Comment on attachment 632188 [details] [diff] [review]
Fix 304 response handling for custom conditional responses and clarify handling of unexpected 304 responses

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

Irving/Gregg:

> Test Pilot is trying to explicitly manage this particular file download to use a 
> local cached version if it is unable to retrieve the on-line version

That code does it's own, custom store of the response data into a file that has nothing to do with the HTTP cache.  AFACIT from glancing over it should work OK with this patch (you seem to handle the 304 case explicitly and use your copy).

	Mark Banner (:standard8)
	Comment 24 • 12 years ago

Apologies for noise, need to clear the now not-necessary Thunderbird tracking flag.

	Alex Keybl [:akeybl]
	Comment 25 • 12 years ago

Bug 746018 has been in the release since FF10. Why should this be tracked for release now? Is this a high volume crash?

	Brian Smith (:briansmith, :bsmith, use NEEDINFO?) Assignee
	Comment 26 • 12 years ago

(In reply to Alex Keybl [:akeybl] from comment #25)
> Bug 746018 has been in the release since FF10. Why should this be tracked
> for release now? Is this a high volume crash?

No, that landed in FF15 and this is a regression since FF15.

	Alex Keybl [:akeybl]
	Comment 27 • 12 years ago

(In reply to Brian Smith (:bsmith) from comment #26)
> (In reply to Alex Keybl [:akeybl] from comment #25)
> > Bug 746018 has been in the release since FF10. Why should this be tracked
> > for release now? Is this a high volume crash?
> 
> No, that landed in FF15 and this is a regression since FF15.

Mistook the "version" for the "target milestone". We'll track this new startup crash regression for FF15 in that case.

	Brian Smith (:briansmith, :bsmith, use NEEDINFO?) Assignee
	Comment 28 • 12 years ago

https://hg.mozilla.org/mozilla-central/rev/28d3f3778315

	Alex Keybl [:akeybl]
	Comment 29 • 12 years ago

(In reply to Brian Smith (:bsmith) from comment #28)
> https://hg.mozilla.org/mozilla-central/rev/28d3f3778315

Is this good to uplift to FF15 at this point? Or does the patch carry significant risk of regression?

	Brian Smith (:briansmith, :bsmith, use NEEDINFO?) Assignee
	Comment 30 • 12 years ago

(In reply to Alex Keybl [:akeybl] from comment #29)
> (In reply to Brian Smith (:bsmith) from comment #28)
> > https://hg.mozilla.org/mozilla-central/rev/28d3f3778315
> 
> Is this good to uplift to FF15 at this point? Or does the patch carry
> significant risk of regression?

This was caused by the patches for bug 746018, which got backed out of Aurora 15 in bug 722034 comment 79.