1397593 - 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)

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: philringnalda [at] gmail.com

https://treeherder.mozilla.org/logviewer.html#?job_id=129008086&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/EhrPHK3TRxOgvu0pyPzJ_w/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Michal Novotny [:michal]]

Looks like this is caused by RCWN.

Comment 2

[Michal Novotny [:michal]]

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.

Comment 3

[Michal Novotny [:michal]]

Attachment: fix

Comment 4

[Michal Novotny [:michal]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=42fa84b479242e4bd178fecdf00e0f18816c1234

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e6f1fbbfdd1f
Assertion failure: !mOnStartRequestCalled (We should not call OnStartRequest twice) in HttpBaseChannel::DoNotifyListener(), r=valentin

Comment 7

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

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

Comment 8

[Valentin Gosu [:valentin] (he/him)]

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

Comment 9

[Michal Novotny [:michal]]

(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?

Comment 10

[Michal Novotny [:michal]]

(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.

Comment 11

[Michal Novotny [:michal]]

Attachment: patch v2

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1c24153baded
Assertion failure: !mOnStartRequestCalled (We should not call OnStartRequest twice) in HttpBaseChannel::DoNotifyListener(), r=valentin

Comment 13

[Firefox Bug Husbandry Bot]

Bulk priority update: https://bugzilla.mozilla.org/show_bug.cgi?id=1399258

Comment 14

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/1c24153baded