Closed Bug 1397593 Opened 7 years ago Closed 7 years ago

Intermittent /content-security-policy/inside-worker/dedicated-inheritance.html | application crashed [@ mozilla::net::HttpBaseChannel::DoNotifyListener()] after Assertion failure: !mOnStartRequestCalled (We should not call OnStartRequest twice)

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla57
Tracking Status
firefox-esr52 --- unaffected
firefox55 --- unaffected
firefox56 --- unaffected
firefox57 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: michal)

References

(Blocks 1 open bug)

Details

(Keywords: crash, intermittent-failure, Whiteboard: [necko-active])

Crash Data

Attachments

(1 file, 1 obsolete file)

Looks like this is caused by RCWN.
Assignee: nobody → michal.novotny
Blocks: RCWN
Component: DOM: Security → Networking: Cache
Whiteboard: [necko-active]
The sequence is as follows:

1) we're racing cache with network
2) network wins and nsHttpChannel::OnStartRequest is called
3) nsHttpChannel::Cancel is called
4) nsHttpChannel::OnCacheEntryAvailable is called but because the channel is canceled nsHttpChannel::OnCacheEntryAvailableInternal fails and AsyncAbort() is called
5) nsHttpChannel::ContinueProcessResponse3 is called and nsHttpChannel::CallOnStartRequest notifies the listener
6) HttpAsyncAborter::HandleAsyncAbort() is called which calls HttpBaseChannel::DoNotifyListener() and the listener is notified again

Looks like the best solution is to avoid calling AsyncAbort when the cache didn't win, because network part should handle any error. OTOH if the cache won, we must abort the channel, because OnStartRequest() will be ignored for the network request.
Attached patch fix (obsolete) — Splinter Review
Attachment #8907014 - Flags: review?(valentin.gosu)
Attachment #8907014 - Flags: review?(valentin.gosu) → review+
Pushed by mnovotny@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e6f1fbbfdd1f
Assertion failure: !mOnStartRequestCalled (We should not call OnStartRequest twice) in HttpBaseChannel::DoNotifyListener(), r=valentin
Backed out for crashing e.g. in xpcshell's toolkit/mozapps/extensions/test/xpcshell/test_LightweightThemeManager.js on Windows:

https://hg.mozilla.org/integration/mozilla-inbound/rev/bb26b7c3357a088b54f08c5c9175ee0ea5c2b2a3

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=e6f1fbbfdd1ffe1c16449a90e918568d3b14c0c6&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=130575785&repo=mozilla-inbound

08:02:19  WARNING -  PROCESS-CRASH | xpcshell-unpack.ini:toolkit/mozapps/extensions/test/xpcshell/test_LightweightThemeManager.js | application crashed [@ mozilla::net::nsHttpChannel::OnCacheEntryAvailable(nsICacheEntry *,bool,nsIApplicationCache *,nsresult)]
08:02:19     INFO -  Crash dump filename: c:\users\genericworker\appdata\local\temp\xpc-other-32jjts\202cf7cc-b236-4a05-a4e0-9276066ab50f.dmp
08:02:19     INFO -  Operating system: Windows NT
08:02:19     INFO -                    6.1.7601 Service Pack 1
08:02:19     INFO -  CPU: x86
08:02:19     INFO -       GenuineIntel family 6 model 63 stepping 2
08:02:19     INFO -       8 CPUs
08:02:19     INFO -  GPU: UNKNOWN
08:02:19     INFO -  Crash reason:  EXCEPTION_BREAKPOINT
08:02:19     INFO -  Crash address: 0x5bce5ada
08:02:19     INFO -  Process uptime: 1 seconds
08:02:19     INFO -  Thread 0 (crashed)
08:02:19     INFO -   0  xul.dll!mozilla::net::nsHttpChannel::OnCacheEntryAvailable(nsICacheEntry *,bool,nsIApplicationCache *,nsresult) [nsHttpChannel.cpp:e6f1fbbfdd1f : 4445 + 0xb]
08:02:19     INFO -      eip = 0x5bce5ada   esp = 0x0022dedc   ebp = 0x0022dee8   ebx = 0x0f42a800
08:02:19     INFO -      esi = 0x0f42adb0   edi = 0xc1f30001   eax = 0x7377e834   ecx = 0x00000000
08:02:19     INFO -      edx = 0x00000001   efl = 0x00000246
08:02:19     INFO -      Found by: given as instruction pointer in context
08:02:19     INFO -   1  xul.dll!mozilla::net::CacheEntry::InvokeAvailableCallback(mozilla::net::CacheEntry::Callback const &) [CacheEntry.cpp:e6f1fbbfdd1f : 850 + 0x13]
08:02:19     INFO -      eip = 0x5bc7f73d   esp = 0x0022def0   ebp = 0x0022df18
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -   2  xul.dll!mozilla::net::CacheEntry::AvailableCallbackRunnable::Run() [CacheEntry.h:e6f1fbbfdd1f : 197 + 0xf]
08:02:19     INFO -      eip = 0x5bc8a40a   esp = 0x0022df20   ebp = 0x0022df24
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -   3  xul.dll!nsThread::ProcessNextEvent(bool,bool *) [nsThread.cpp:e6f1fbbfdd1f : 1039 + 0xc]
08:02:19     INFO -      eip = 0x5bb108de   esp = 0x0022df2c   ebp = 0x0022e4a0
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -   4  xul.dll + 0x25589c0
08:02:19     INFO -      eip = 0x5d9f89c0   esp = 0x0022df8c   ebp = 0x0022e4f8
08:02:19     INFO -      Found by: stack scanning
08:02:19     INFO -   5  0x22e51c
08:02:19     INFO -      eip = 0x0022e51c   esp = 0x0022e500   ebp = 0x0ddbb140
08:02:19     INFO -      Found by: previous frame's frame pointer
08:02:19     INFO -   6  xul.dll!mozilla::net::nsSocketTransportService::ShutdownThread() [nsSocketTransportService2.cpp:e6f1fbbfdd1f : 638 + 0xb]
08:02:19     INFO -      eip = 0x5bb7a957   esp = 0x0022e504   ebp = 0x0022e51c
08:02:19     INFO -      Found by: stack scanning
08:02:19     INFO -   7  xul.dll!mozilla::net::nsSocketTransportService::Shutdown(bool) [nsSocketTransportService2.cpp:e6f1fbbfdd1f : 621 + 0x7]
08:02:19     INFO -      eip = 0x5bb7a8d6   esp = 0x0022e524   ebp = 0x0022e528
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -   8  xul.dll!mozilla::net::nsIOService::SetOffline(bool) [nsIOService.cpp:e6f1fbbfdd1f : 1171 + 0x12]
08:02:19     INFO -      eip = 0x5bb61ca4   esp = 0x0022e530   ebp = 0x0022e544
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -   9  xul.dll!mozilla::net::nsIOService::Observe(nsISupports *,char const *,char16_t const *) [nsIOService.cpp:e6f1fbbfdd1f : 1482 + 0xb]
08:02:19     INFO -      eip = 0x5bb5b9f7   esp = 0x0022e54c   ebp = 0x0022e620
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -  10  xul.dll!nsObserverList::NotifyObservers(nsISupports *,char const *,char16_t const *) [nsObserverList.cpp:e6f1fbbfdd1f : 112 + 0x1a]
08:02:19     INFO -      eip = 0x5bae130c   esp = 0x0022e628   ebp = 0x0022e640
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -  11  xul.dll!nsObserverService::NotifyObservers(nsISupports *,char const *,char16_t const *) [nsObserverService.cpp:e6f1fbbfdd1f : 296 + 0xe]
08:02:19     INFO -      eip = 0x5bae13e8   esp = 0x0022e648   ebp = 0x0022e6ac
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -  12  xul.dll!NS_InvokeByIndex + 0x27
08:02:19     INFO -      eip = 0x5bb17537   esp = 0x0022e6b4   ebp = 0x0022e6d0
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -  13  xul.dll!XPCWrappedNative::CallMethod(XPCCallContext &,XPCWrappedNative::CallMode) [XPCWrappedNative.cpp:e6f1fbbfdd1f : 1282 + 0xb04]
08:02:19     INFO -      eip = 0x5bf723c8   esp = 0x0022e6d8   ebp = 0x0022e868
08:02:19     INFO -      Found by: previous frame's frame pointer
08:02:19     INFO -  14  xul.dll!js::InternalCallOrConstruct(JSContext *,JS::CallArgs const &,js::MaybeConstruct) [Interpreter.cpp:e6f1fbbfdd1f : 495 + 0x56]
08:02:19     INFO -      eip = 0x5db2c22b   esp = 0x0022e748   ebp = 0x0022e868
08:02:19     INFO -      Found by: stack scanning
08:02:19     INFO -  15  xul.dll!XPC_WN_CallMethod(JSContext *,unsigned int,JS::Value *) [XPCWrappedNativeJSOps.cpp:e6f1fbbfdd1f : 928 + 0xb]
08:02:19     INFO -      eip = 0x5bf7f3ad   esp = 0x0022e870   ebp = 0x0022e908
08:02:19     INFO -      Found by: call frame info
08:02:19     INFO -  16  xul.dll!XPC_WN_CallMethod(JSContext *,unsigned int,JS::Value *) [XPCWrappedNativeJSOps.cpp:e6f1fbbfdd1f : 928 + 0xb]
08:02:19     INFO -      eip = 0x5bf7f3ad   esp = 0x0022e878   ebp = 0x0022e908
08:02:19     INFO -      Found by: stack scanning
08:02:19     INFO -  17  xul.dll!js::InternalCallOrConstruct(JSContext *,JS::CallArgs const &,js::MaybeConstruct) [Interpreter.cpp:e6f1fbbfdd1f : 495 + 0x56]
08:02:19     INFO -      eip = 0x5db2c22b   esp = 0x0022e910   ebp = 0x0022e908
08:02:19     INFO -      Found by: stack scanning
Flags: needinfo?(michal.novotny)
Comment on attachment 8907014 [details] [diff] [review]
fix

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

::: netwerk/protocol/http/nsHttpChannel.cpp
@@ +4441,5 @@
> +            // Ignore the error if we're racing cache with network and the cache
> +            // didn't win, The network part will handle cancelation or any other
> +            // error. Otherwise we could end up calling the listener twice, see
> +            // bug 1397593.
> +            MOZ_RELEASE_ASSERT(mRaceCacheWithNetwork);

It seems we fail the common case, where mRaceCacheWithNetwork == false (mNetworkTriggered can still be true), and mFirstResponseSource == RESPONSE_PENDING
(In reply to Valentin Gosu [:valentin] from comment #8)
> Comment on attachment 8907014 [details] [diff] [review]
> fix
> 
> Review of attachment 8907014 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: netwerk/protocol/http/nsHttpChannel.cpp
> @@ +4441,5 @@
> > +            // Ignore the error if we're racing cache with network and the cache
> > +            // didn't win, The network part will handle cancelation or any other
> > +            // error. Otherwise we could end up calling the listener twice, see
> > +            // bug 1397593.
> > +            MOZ_RELEASE_ASSERT(mRaceCacheWithNetwork);
> 
> It seems we fail the common case, where mRaceCacheWithNetwork == false
> (mNetworkTriggered can still be true), and mFirstResponseSource ==
> RESPONSE_PENDING

How mNetworkTriggered could be true when we didn't get the entry yet and we're not racing?
Flags: needinfo?(michal.novotny) → needinfo?(valentin.gosu)
(In reply to Michal Novotny (:michal) from comment #9)
> How mNetworkTriggered could be true when we didn't get the entry yet and
> we're not racing?

IMO the only possibility is that TriggerNetwork() is called in OnCacheEntryAvailableInternal() and it fails for some reason.
Flags: needinfo?(valentin.gosu)
Attached patch patch v2Splinter Review
Attachment #8907014 - Attachment is obsolete: true
Attachment #8907490 - Flags: review?(valentin.gosu)
Attachment #8907490 - Flags: review?(valentin.gosu) → review+
Pushed by mnovotny@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1c24153baded
Assertion failure: !mOnStartRequestCalled (We should not call OnStartRequest twice) in HttpBaseChannel::DoNotifyListener(), r=valentin
Bulk priority update: https://bugzilla.mozilla.org/show_bug.cgi?id=1399258
Priority: P5 → P1
https://hg.mozilla.org/mozilla-central/rev/1c24153baded
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
You need to log in before you can comment on or make changes to this bug.