1313923 - File doesn't download; assertion in debug build

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Josh Matthews [:jdm]]

I observe this problem in my default profile with safe mode; I have not been able to replicate it in a new profile yet. I'd love suggestions about things I could try!

STR:
1. Visit http://emshort.com/counterfeit_monkey/index.html
2. Click the "Story File" link
3. Save the file somewhere.

Expected:
File saves as expected.

Actual:
File download never begins; debug builds show the following assertion:

Assertion failure: ((bool)(__builtin_expect(!!(!NS_FAILED_impl(rv)), 1))) || rv == NS_ERROR_NOT_AVAILABLE, at /Users/jdm/src/mozilla-central/netwerk/protocol/http/HttpChannelParent.cpp:1334
#01: mozilla::net::HttpChannelParent::SuspendForDiversion()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x885788]
#02: non-virtual thunk to mozilla::net::HttpChannelParent::SuspendForDiversion()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x888539]
#03: mozilla::net::ChannelDiverterParent::Init(mozilla::net::ChannelDiverterArgs const&)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x2cba7d]
#04: mozilla::net::NeckoParent::RecvPChannelDiverterConstructor(mozilla::net::PChannelDiverterParent*, mozilla::net::ChannelDiverterArgs const&)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x9aeae9]
#05: mozilla::net::PNeckoParent::OnMessageReceived(IPC::Message const&)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xee8e5e]
#06: mozilla::dom::PContentParent::OnMessageReceived(IPC::Message const&)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x13a8985]
#07: mozilla::ipc::MessageChannel::DispatchAsyncMessage(IPC::Message const&)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbcb929]
#08: mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbca714]
#09: mozilla::ipc::MessageChannel::OnMaybeDequeueOne()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbc35f2]
#10: decltype(*(fp).*fp0(Get<>(fp1).PassAsParameter())) mozilla::detail::RunnableMethodArguments<>::applyImpl<mozilla::ipc::MessageChannel, bool (mozilla::ipc::MessageChannel::*)()>(mozilla::ipc::MessageChannel*, bool (mozilla::ipc::MessageChannel::*)(), mozil[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbed7ba]
#11: _ZN7mozilla6detail23RunnableMethodArgumentsIJEE5applyINS_3ipc14MessageChannelEMS5_FbvEEEDTcl9applyImplfp_fp0_dtdefpT10mArgumentscvNS_13IndexSequenceIJEEE_EEEPT_T0_[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbed729]
#12: mozilla::detail::RunnableMethodImpl<bool (mozilla::ipc::MessageChannel::*)(), false, true>::Run()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbed4f2]
#13: mozilla::ipc::MessageChannel::RefCountedTask::Run()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbea2d2]
#14: mozilla::ipc::MessageChannel::DequeueTask::Run()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbea068]
#15: nsThread::ProcessNextEvent(bool, bool*)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x1c79be]
#16: NS_ProcessPendingEvents(nsIThread*, unsigned int)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x254291]
#17: nsBaseAppShell::NativeEventCallback()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x4aa4a0e]
#18: nsAppShell::ProcessGeckoEvents(void*)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x4b3cf42]
#19: __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__[/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation +0x7f5b1]
#20: __CFRunLoopDoSources0[/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation +0x70c62]
#21: __CFRunLoopRun[/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation +0x703ef]
#22: CFRunLoopRunSpecific[/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation +0x6fe75]
#23: RunCurrentEventLoopInMode[/System/Library/Frameworks/Carbon.framework/Versions/A/Frameworks/HIToolbox.framework/Versions/A/HIToolbox +0x2ea0d]
#24: ReceiveNextEventCommon[/System/Library/Frameworks/Carbon.framework/Versions/A/Frameworks/HIToolbox.framework/Versions/A/HIToolbox +0x2e7b7]
#25: _BlockUntilNextEventMatchingListInModeWithFilter[/System/Library/Frameworks/Carbon.framework/Versions/A/Frameworks/HIToolbox.framework/Versions/A/HIToolbox +0x2e5bc]
#26: _DPSNextEvent[/System/Library/Frameworks/AppKit.framework/Versions/C/AppKit +0x2424e]
#27: -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:][/System/Library/Frameworks/AppKit.framework/Versions/C/AppKit +0x2389b]
#28: -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:][/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x4b3bad4]
#29: -[NSApplication run][/System/Library/Frameworks/AppKit.framework/Versions/C/AppKit +0x1799c]
#30: nsAppShell::Run()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x4b3d8dc]
#31: nsAppStartup::Run()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x5f7470b]
#32: XREMain::XRE_mainRun()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x608f7ad]
#33: XREMain::XRE_main(int, char**, nsXREAppData const*)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x6090241]
#34: XRE_main[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0x60906a2]
#35: do_main(int, char**, char**, nsIFile*)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/firefox +0x18b3]
#36: main[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/firefox +0xdc2]
[Child 35026] ###!!! ABORT: Aborting on channel error.: file /Users/jdm/src/mozilla-central/ipc/glue/MessageChannel.cpp, line 2070
Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=25.898) #01: mozilla::ipc::MessageChannel::OnChannelErrorFromLink()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbcc4a2]
#02: mozilla::ipc::ProcessLink::OnChannelError()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbce4e7]
#03: non-virtual thunk to mozilla::ipc::ProcessLink::OnChannelError()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbce519]
#04: IPC::Channel::ChannelImpl::OnFileCanReadWithoutBlocking(int)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb3a6c2]
#05: base::MessagePumpLibevent::OnLibeventNotification(int, short, void*)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xad7194]
#06: event_persist_closure[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb987ad]
#07: event_process_active_single_queue[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb98069]
#08: event_process_active[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb81fc3]
#09: event_base_loop[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb8117c]
#10: base::MessagePumpLibevent::Run(base::MessagePump::Delegate*)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xad75b4]
#11: MessageLoop::RunInternal()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xad4395]
#12: MessageLoop::RunHandler()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xad42f5]
#13: MessageLoop::Run()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xad429d]
#14: base::Thread::ThreadMain()[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb112ff]
#15: ThreadFunc(void*)[/Users/jdm/src/mozilla-central/obj-x86_64-apple-darwin13.4.0/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb11e8e]
#16: _pthread_body[/usr/lib/system/libsystem_pthread.dylib +0x1899]
#17: _pthread_struct_init[/usr/lib/system/libsystem_pthread.dylib +0x172a]
[Child 35026] ###!!! ABORT: Aborting on channel error.: file /Users/jdm/src/mozilla-central/ipc/glue/MessageChannel.cpp, line 2070

Comment 1

[Josh Matthews [:jdm]]

Attachment: HTTP log

Comment 2

[Honza Bambas (:mayhemer)]

You may be hitting https://dxr.mozilla.org/mozilla-central/rev/e3279760cd977aac30bd9e8032d3ee71f55d2a67/netwerk/base/nsInputStreamPump.cpp#229

Could be a race condition on the pump state, and IMO it's legal.  I'd personally remove that assertion.  If suspend fails, we handle it correctly.

Comment 3

[Honza Bambas (:mayhemer)]

Hmm.. I overlook the start of the comment 0.  Anyway, are you sure that exactly this assertion failure is related to the download not begin started?

Could this relate to bug 1259305?

Comment 4

[Josh Matthews [:jdm]]

I am not sure, since the assertion is completely reproducible in the profile that reproduces the issue and it takes down the content process.

Comment 5

[Ben Kelly [:bkelly, not reviewing]]

I've paged out all my knowledge on e10s diversion stuff.  It looks like Honza and Josh might have some ideas here, though.  Dropping the NI for now.

Comment 6

[Dragana Damjanovic [:dragana]]

From the log:
[Parent 35005] WARNING: NS_ENSURE_TRUE(mState != STATE_IDLE) failed: file /Users/jdm/src/mozilla-central/netwerk/base/nsInputStreamPump.cpp, line 229

this cause the assertion to fail.

Comment 7

[Dragana Damjanovic [:dragana]]

(In reply to Josh Matthews [:jdm] from comment #4)
> I am not sure, since the assertion is completely reproducible in the profile
> that reproduces the issue and it takes down the content process.

Can you make a full http log?
I am not sure if we have enough log in the streampump to figure out what is happening :(

Comment 8

[Josh Matthews [:jdm]]

Interestingly, I have now lost the ability to replicate the problem in a debug build, while the nightly binary replicates it fine (both using the same profile).

Comment 9

[Josh Matthews [:jdm]]

Attachment: Parent process HTTP log

Comment 10

[Josh Matthews [:jdm]]

Attachment: Child process HTTP log

Comment 11

[Josh Matthews [:jdm]]

Attachment: Child process HTTP log

Comment 12

[Josh Matthews [:jdm]]

Attachment: nspr-better-log

Comment 13

[Josh Matthews [:jdm]]

These logs were made using MOZ_LOG=nsHttp:5,nsSocketTransport:5,nsStreamPump:5,nsHostResolver:5,sync

Comment 14

[Dragana Damjanovic [:dragana]]

Thank you for the log, it was helpful.

The crash is caused by partial read from the cache:
[Main Thread]: V/nsHttp HttpChannelParentListener::OnDataAvailable [this=12364b290]
[Main Thread]: V/nsHttp HttpChannelParent::OnDataAvailable [this=13d247ab0 aRequest=13c231048]
[Main Thread]: D/nsStreamPump   OnStateStop [this=13c363c50 status=0]
[Main Thread]: D/nsHttp nsHttpChannel::OnStopRequest [this=13c231000 request=13c363c50 status=0]
[Main Thread]: D/nsHttp   dropping upload stream
[Main Thread]: D/nsHttp nsHttpChannel::OnDoneReadingPartialCacheEntry [this=13c231000]

in log above we have finished reading partial cache entry, and inputStreamPump is set to STATE_IDLE.

later we try to suspend the channel for a diversion:
[Main Thread]: V/nsHttp HttpChannelParent::SuspendForDiversion [this=13d247ab0]
[Main Thread]: D/nsHttp nsHttpChannel::SuspendInternal [this=13c231000]
[Main Thread]: D/nsStreamPump nsInputStreamPump::Suspend [this=140bf8470]
[Main Thread]: D/nsStreamPump nsInputStreamPump::Suspend [this=13c363c50]

the second pump is the cache pump that was already finished and is in the STATE_IDLE state.

Honza, can we just set mCachePump to nullptr when partial read finishes? I will make a patch.

Comment 15

[Dragana Damjanovic [:dragana]]

Attachment: bug_1313923.patch

Comment 16

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=7337b429dfbe7bfd72afe7e3cbda17772413b355

Comment 17

[Honza Bambas (:mayhemer)]

Comment on attachment 8806689 [details] [diff] [review]
bug_1313923.patch

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

I went through the http channel and checked all the places we use cache pump to branch.  It's safe to throw it away here, yes.

::: netwerk/protocol/http/nsHttpChannel.cpp
@@ +3127,5 @@
>  
>      // we're now completing the cached content, so we can clear this flag.
>      // this puts us in the state of a regular download.
>      mCachedContentIsPartial = false;
> +    mCachePump = nullptr;

please add a comment why we are releasing the pump here (and maybe why it's safe to do it?)

Comment 18

[Dragana Damjanovic [:dragana]]

Attachment: bug_1313923.patch

Comment 19

[Honza Bambas (:mayhemer)]

Comment on attachment 8807074 [details] [diff] [review]
bug_1313923.patch

>+    // The cache input stream pump is finished, we do not need it any more.
>+    // (see bug 1313923)
>+    mCachePump = nullptr;

Ehm... just for the next time, the comment just says what's obvious from the code.  Purpose of a comment is to say WHY you are doing the thing, not just say "yes, I'm doing it".  Reference to a bug# is usually not the right way to go.  It can be found (with some effort) via blame..  But as I say, just for the next time.

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/6b931b75a6d2
Drop reference to the cache pump after a cache partial read finishes. r=mayhemer

Comment 21

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/6b931b75a6d2