Closed Bug 1648002 Opened 4 years ago Closed 1 year ago

Intermittent Assertion failure: mInsideLoop, at /builds/worker/checkouts/gecko/netwerk/cache2/CacheIOThread.cpp:584

Categories

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

defect

Tracking

()

RESOLVED FIXED
121 Branch
Tracking Status
firefox-esr115 --- wontfix
firefox119 --- wontfix
firefox120 --- wontfix
firefox121 --- fixed

People

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

References

(Blocks 1 open bug)

Details

(Keywords: assertion, intermittent-failure, Whiteboard: [necko-triaged])

Attachments

(1 file)

Unlikely this is related to the form control reftests which ran before this assertion fired.

Component: Layout: Form Controls → Networking: Cache

I'll rewrite the shutdown logic of the xpcom thread to asyncshutdown it. then dispatch will gracefully fail and we will no longer need to do the assertion.

Assignee: nobody → honzab.moz
Status: NEW → ASSIGNED
Assignee: honzab.moz → nobody
Status: ASSIGNED → NEW
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=323980220&repo=mozilla-central&lineNumber=2286

[task 2020-12-08T22:04:50.268Z] 22:04:50 INFO - TEST-START | browser/components/extensions/test/mochitest/test_ext_all_apis.html
[task 2020-12-08T22:04:51.336Z] 22:04:51 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: Cannot record shutdown step, mConnection is nullptr: file /builds/worker/checkouts/gecko/dom/localstorage/ActorsParent.cpp:8027
[task 2020-12-08T22:04:51.936Z] 22:04:51 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: Cannot record shutdown step, mConnection is nullptr: file /builds/worker/checkouts/gecko/dom/localstorage/ActorsParent.cpp:8027
[task 2020-12-08T22:04:52.276Z] 22:04:52 INFO - GECKO(1519) | [Child 1606, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2020-12-08T22:04:52.277Z] 22:04:52 INFO - GECKO(1519) | [Child 1606, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2020-12-08T22:04:52.343Z] 22:04:52 INFO - GECKO(1519) | [Parent 1519, Main Thread] WARNING: Need BrowserChild to get the nativeWindow from!: file /builds/worker/checkouts/gecko/widget/PuppetWidget.cpp:1041
[task 2020-12-08T22:04:52.366Z] 22:04:52 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2745
[task 2020-12-08T22:04:53.027Z] 22:04:53 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2020-12-08T22:04:53.028Z] 22:04:53 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2020-12-08T22:04:53.055Z] 22:04:53 INFO - GECKO(1519) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2020-12-08T22:04:53.055Z] 22:04:53 INFO - GECKO(1519) | MEMORY STAT | vsize 2566MB | residentFast 163MB | heapAllocated 13MB
[task 2020-12-08T22:04:53.132Z] 22:04:53 INFO - TEST-OK | browser/components/extensions/test/mochitest/test_ext_all_apis.html | took 2866ms
[task 2020-12-08T22:04:53.156Z] 22:04:53 INFO - TEST-START | Shutdown
[task 2020-12-08T22:04:53.156Z] 22:04:53 INFO - Passed: 2
[task 2020-12-08T22:04:53.157Z] 22:04:53 INFO - Failed: 0
[task 2020-12-08T22:04:53.165Z] 22:04:53 INFO - Todo: 0
[task 2020-12-08T22:04:53.165Z] 22:04:53 INFO - Mode: e10s
[task 2020-12-08T22:04:53.165Z] 22:04:53 INFO - Slowest: 2866ms - /tests/browser/components/extensions/test/mochitest/test_ext_all_apis.html
[task 2020-12-08T22:04:53.166Z] 22:04:53 INFO - SimpleTest FINISHED
[task 2020-12-08T22:04:53.166Z] 22:04:53 INFO - TEST-INFO | Ran 1 Loops
[task 2020-12-08T22:04:53.167Z] 22:04:53 INFO - SimpleTest FINISHED
[task 2020-12-08T22:04:53.392Z] 22:04:53 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2020-12-08T22:04:53.394Z] 22:04:53 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2020-12-08T22:04:53.402Z] 22:04:53 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2020-12-08T22:04:53.422Z] 22:04:53 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2020-12-08T22:04:53.423Z] 22:04:53 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2020-12-08T22:04:53.444Z] 22:04:53 INFO - GECKO(1519) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 573: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2020-12-08T22:04:53.553Z] 22:04:53 INFO - GECKO(1519) | [Child 1669, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/caps/BasePrincipal.cpp:1349
[task 2020-12-08T22:04:53.629Z] 22:04:53 INFO - GECKO(1519) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-12-08T22:04:53.630Z] 22:04:53 INFO - GECKO(1519) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-12-08T22:04:53.630Z] 22:04:53 INFO - GECKO(1519) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-12-08T22:04:53.670Z] 22:04:53 INFO - GECKO(1519) | [Parent 1519, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/netwerk/cache/nsApplicationCacheService.cpp:161
[task 2020-12-08T22:04:53.751Z] 22:04:53 INFO - GECKO(1519) | [WARN xulstore::persist] tried to remove key that isn't in the store
[task 2020-12-08T22:04:53.751Z] 22:04:53 INFO - GECKO(1519) | [WARN xulstore::persist] tried to remove key that isn't in the store
[task 2020-12-08T22:04:54.343Z] 22:04:54 INFO - GECKO(1519) | [Child 1606, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3360
[task 2020-12-08T22:04:54.383Z] 22:04:54 INFO - GECKO(1519) | [Child 1606, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4339
[task 2020-12-08T22:04:54.451Z] 22:04:54 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3360
[task 2020-12-08T22:04:54.472Z] 22:04:54 INFO - GECKO(1519) | [Child 1582, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4339
[task 2020-12-08T22:04:54.536Z] 22:04:54 INFO - GECKO(1519) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-12-08T22:04:54.537Z] 22:04:54 INFO - GECKO(1519) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-12-08T22:04:54.539Z] 22:04:54 INFO - GECKO(1519) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-12-08T22:04:54.597Z] 22:04:54 INFO - GECKO(1519) | Assertion failure: mInsideLoop, at /builds/worker/checkouts/gecko/netwerk/cache2/CacheIOThread.cpp:583
[task 2020-12-08T22:04:54.618Z] 22:04:54 INFO - Initializing stack-fixing for the first stack frame, this may take a while...
[task 2020-12-08T22:05:00.487Z] 22:05:00 INFO - GECKO(1519) | #01: mozilla::ThreadEventQueue::PutEventInternal(already_AddRefed<nsIRunnable>&&, mozilla::EventQueuePriority, mozilla::ThreadEventQueue::NestedSink*) [xpcom/threads/ThreadEventQueue.cpp:124]
[task 2020-12-08T22:05:00.488Z] 22:05:00 INFO - GECKO(1519) | #02: mozilla::ThreadEventTarget::Dispatch(already_AddRefed<nsIRunnable>, unsigned int) [xpcom/threads/ThreadEventTarget.cpp:101]
[task 2020-12-08T22:05:00.488Z] 22:05:00 INFO - GECKO(1519) | #03: nsThread::Dispatch(already_AddRefed<nsIRunnable>, unsigned int) [xpcom/threads/nsThread.cpp:707]
[task 2020-12-08T22:05:00.489Z] 22:05:00 INFO - GECKO(1519) | #04: nsIEventTarget::Dispatch(nsIRunnable*, unsigned int) [s3:gecko-generated-sources:d72bcb61713baa8aa2a5b1e747d00f3902e1243598ecfb27626316992a99323173c809fcd527edf55c1f869ebd41ca32c85b18a314efc99b582036bc6928b48e/dist/include/nsIEventTarget.h::41]
[task 2020-12-08T22:05:00.490Z] 22:05:00 INFO - GECKO(1519) | #05: TimerThread::PostTimerEvent(already_AddRefed<nsTimerImpl>) [xpcom/threads/TimerThread.cpp:733]
[task 2020-12-08T22:05:00.490Z] 22:05:00 INFO - GECKO(1519) | #06: TimerThread::Run() [xpcom/threads/TimerThread.cpp:417]
[task 2020-12-08T22:05:00.490Z] 22:05:00 INFO - GECKO(1519) | #07: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1200]
[task 2020-12-08T22:05:00.491Z] 22:05:00 INFO - GECKO(1519) | #08: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:548]
[task 2020-12-08T22:05:00.498Z] 22:05:00 INFO - GECKO(1519) | #09: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:303]
[task 2020-12-08T22:05:00.499Z] 22:05:00 INFO - GECKO(1519) | #10: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:334]
[task 2020-12-08T22:05:00.499Z] 22:05:00 INFO - GECKO(1519) | #11: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:310]
[task 2020-12-08T22:05:00.499Z] 22:05:00 INFO - GECKO(1519) | #12: nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:443]
[task 2020-12-08T22:05:00.500Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.000001s: starting', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.500Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: cache shutdown step: '0.000001s: starting', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.500Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: sdb shutdown step: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.501Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: ls shutdown step: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.511Z] 22:05:00 INFO - GECKO(1519) | #13: pt_root [nsprpub/pr/src/pthreads/ptthread.c:204]
[task 2020-12-08T22:05:00.512Z] 22:05:00 INFO - fix-stacks: error: failed to read symbols file /builds/worker/workspace/build/symbols/libpthread.so.0/10063CBC74776C265F7DB3F1F380A3DA0/libpthread.so.0.sym for /lib/x86_64-linux-gnu/libpthread.so.0
[task 2020-12-08T22:05:00.512Z] 22:05:00 INFO - fix-stacks: note: this is expected and harmless for system libraries on debug automation runs
[task 2020-12-08T22:05:00.512Z] 22:05:00 INFO - fix-stacks: No such file or directory (os error 2)
[task 2020-12-08T22:05:00.512Z] 22:05:00 INFO - GECKO(1519) | #14: ??? [/lib/x86_64-linux-gnu/libpthread.so.0 + 0x76db]
[task 2020-12-08T22:05:00.512Z] 22:05:00 INFO - fix-stacks: error: failed to read symbols file /builds/worker/workspace/build/symbols/libc.so.6/4B76CFD3972F3EACFE366DDD07AD902F0/libc.so.6.sym for /lib/x86_64-linux-gnu/libc.so.6
[task 2020-12-08T22:05:00.513Z] 22:05:00 INFO - fix-stacks: note: this is expected and harmless for system libraries on debug automation runs
[task 2020-12-08T22:05:00.513Z] 22:05:00 INFO - fix-stacks: No such file or directory (os error 2)
[task 2020-12-08T22:05:00.513Z] 22:05:00 INFO - GECKO(1519) | #15: clone [/lib/x86_64-linux-gnu/libc.so.6 + 0x121a3f]
[task 2020-12-08T22:05:00.513Z] 22:05:00 INFO - GECKO(1519) | #16: ??? (???:???)
[task 2020-12-08T22:05:00.514Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.006101s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.514Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.006126s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.514Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.006276s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.514Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.006286s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.514Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.008084s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.515Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.008122s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.515Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.008133s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.515Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.008172s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.515Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.008179s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.516Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: idb shutdown step: '0.008196s: completed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.516Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: cache shutdown step: '0.007443s: completed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.516Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: sdb shutdown step: '0.007436s: completed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.516Z] 22:05:00 INFO - GECKO(1519) | [Parent 1519, IPDL Background] WARNING: ls shutdown step: '0.007436s: completed', file /builds/worker/checkouts/gecko/dom/quota/Client.cpp:279
[task 2020-12-08T22:05:00.516Z] 22:05:00 INFO - GECKO(1519) | ExceptionHandler::GenerateDump cloned child 1744
[task 2020-12-08T22:05:00.516Z] 22:05:00 INFO - GECKO(1519) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2020-12-08T22:05:00.516Z] 22:05:00 INFO - GECKO(1519) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2020-12-08T22:05:00.517Z] 22:05:00 INFO - GECKO(1519) | [Child 1699, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3360
[task 2020-12-08T22:05:00.517Z] 22:05:00 INFO - GECKO(1519) | [Child 1699, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4339
[task 2020-12-08T22:05:00.517Z] 22:05:00 INFO - GECKO(1519) | [Child 1669, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3360
[task 2020-12-08T22:05:00.517Z] 22:05:00 INFO - GECKO(1519) | [Child 1669, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4339
[task 2020-12-08T22:05:00.552Z] 22:05:00 INFO - TEST-INFO | Main app process: exit 11
[task 2020-12-08T22:05:00.553Z] 22:05:00 INFO - Buffered messages finished
[task 2020-12-08T22:05:00.554Z] 22:05:00 ERROR - TEST-UNEXPECTED-FAIL | Last test finished | application terminated with exit code 11
[task 2020-12-08T22:05:00.554Z] 22:05:00 INFO - runtests.py | Application ran for: 0:00:18.761731
[task 2020-12-08T22:05:00.555Z] 22:05:00 INFO - zombiecheck | Reading PID log: /tmp/tmp9h0i8Lpidlog
[task 2020-12-08T22:05:00.555Z] 22:05:00 INFO - ==> process 1519 launched child process 1543
[task 2020-12-08T22:05:00.556Z] 22:05:00 INFO - ==> process 1519 launched child process 1582
[task 2020-12-08T22:05:00.557Z] 22:05:00 INFO - ==> process 1519 launched child process 1606
[task 2020-12-08T22:05:00.557Z] 22:05:00 INFO - ==> process 1519 launched child process 1669
[task 2020-12-08T22:05:00.558Z] 22:05:00 INFO - ==> process 1519 launched child process 1699
[task 2020-12-08T22:05:00.559Z] 22:05:00 INFO - zombiecheck | Checking for orphan process with PID: 1669
[task 2020-12-08T22:05:00.559Z] 22:05:00 INFO - zombiecheck | Checking for orphan process with PID: 1699
[task 2020-12-08T22:05:00.560Z] 22:05:00 INFO - zombiecheck | Checking for orphan process with PID: 1606
[task 2020-12-08T22:05:00.561Z] 22:05:00 INFO - zombiecheck | Checking for orphan process with PID: 1582
[task 2020-12-08T22:05:00.561Z] 22:05:00 INFO - zombiecheck | Checking for orphan process with PID: 1543
[task 2020-12-08T22:05:00.562Z] 22:05:00 INFO - mozcrash Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk /tmp/tmpeI2BJ
.mozrunner/minidumps/6567adee-9159-a037-289b-3c0e2305d23c.dmp /builds/worker/workspace/build/symbols
[task 2020-12-08T22:05:05.909Z] 22:05:05 INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/6567adee-9159-a037-289b-3c0e2305d23c.dmp
[task 2020-12-08T22:05:05.910Z] 22:05:05 INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/6567adee-9159-a037-289b-3c0e2305d23c.extra
[task 2020-12-08T22:05:06.034Z] 22:05:06 INFO - PROCESS-CRASH | Last test finished | application crashed [@ mozilla::net::CacheIOThread::OnDispatchedEvent()]
[task 2020-12-08T22:05:06.035Z] 22:05:06 INFO - Mozilla crash reason: MOZ_ASSERT(mInsideLoop)
[task 2020-12-08T22:05:06.035Z] 22:05:06 INFO - Crash dump filename: /tmp/tmpeI2BJ_.mozrunner/minidumps/6567adee-9159-a037-289b-3c0e2305d23c.dmp
[task 2020-12-08T22:05:06.035Z] 22:05:06 INFO - Operating system: Linux
[task 2020-12-08T22:05:06.035Z] 22:05:06 INFO - 0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64
[task 2020-12-08T22:05:06.035Z] 22:05:06 INFO - CPU: amd64
[task 2020-12-08T22:05:06.036Z] 22:05:06 INFO - family 6 model 85 stepping 7
[task 2020-12-08T22:05:06.036Z] 22:05:06 INFO - 2 CPUs
[task 2020-12-08T22:05:06.036Z] 22:05:06 INFO -
[task 2020-12-08T22:05:06.037Z] 22:05:06 INFO - GPU: UNKNOWN
[task 2020-12-08T22:05:06.037Z] 22:05:06 INFO -
[task 2020-12-08T22:05:06.037Z] 22:05:06 INFO - Crash reason: SIGSEGV /SEGV_MAPERR
[task 2020-12-08T22:05:06.037Z] 22:05:06 INFO - Crash address: 0x0
[task 2020-12-08T22:05:06.037Z] 22:05:06 INFO - Process uptime: not available
[task 2020-12-08T22:05:06.038Z] 22:05:06 INFO -
[task 2020-12-08T22:05:06.038Z] 22:05:06 INFO - Thread 9 (crashed)
[task 2020-12-08T22:05:06.038Z] 22:05:06 INFO - 0 libxul.so!mozilla::net::CacheIOThread::OnDispatchedEvent() [CacheIOThread.cpp:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 583 + 0x29]
[task 2020-12-08T22:05:06.038Z] 22:05:06 INFO - rax = 0x00007fc5c06638e4 rdx = 0x0000000000000000
[task 2020-12-08T22:05:06.038Z] 22:05:06 INFO - rcx = 0x000055c05e4a49f8 rbx = 0x00007fc5bdd18480
[task 2020-12-08T22:05:06.039Z] 22:05:06 INFO - rsi = 0x00007fc5d3cfe8b0 rdi = 0x00007fc5d3cfd680
[task 2020-12-08T22:05:06.039Z] 22:05:06 INFO - rbp = 0x00007fc5b717c7e0 rsp = 0x00007fc5b717c7d0
[task 2020-12-08T22:05:06.039Z] 22:05:06 INFO - r8 = 0x00007fc5d3cfe8b0 r9 = 0x00007fc5b717d700
[task 2020-12-08T22:05:06.039Z] 22:05:06 INFO - r10 = 0x0000000000000002 r11 = 0x0000000000000000
[task 2020-12-08T22:05:06.039Z] 22:05:06 INFO - r12 = 0x0000000000000000 r13 = 0x00007fc5bcb15820
[task 2020-12-08T22:05:06.040Z] 22:05:06 INFO - r14 = 0x00007fc5bdd18498 r15 = 0x00007fc5b51fd1b0
[task 2020-12-08T22:05:06.040Z] 22:05:06 INFO - rip = 0x00007fc5c3428bd1
[task 2020-12-08T22:05:06.040Z] 22:05:06 INFO - Found by: given as instruction pointer in context
[task 2020-12-08T22:05:06.040Z] 22:05:06 INFO - 1 libxul.so!mozilla::ThreadEventQueue::PutEventInternal(already_AddRefed<nsIRunnable>&&, mozilla::EventQueuePriority, mozilla::ThreadEventQueue::NestedSink*) [ThreadEventQueue.cpp:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 124 + 0xe]
[task 2020-12-08T22:05:06.040Z] 22:05:06 INFO - rbx = 0x00007fc5bdd18401 rbp = 0x00007fc5b717c840
[task 2020-12-08T22:05:06.041Z] 22:05:06 INFO - rsp = 0x00007fc5b717c7f0 r12 = 0x0000000000000000
[task 2020-12-08T22:05:06.041Z] 22:05:06 INFO - r13 = 0x00007fc5bcb15820 r14 = 0x00007fc5b717c808
[task 2020-12-08T22:05:06.041Z] 22:05:06 INFO - r15 = 0x00007fc5b51fd1b0 rip = 0x00007fc5c309b93a
[task 2020-12-08T22:05:06.041Z] 22:05:06 INFO - Found by: call frame info
[task 2020-12-08T22:05:06.041Z] 22:05:06 INFO - 2 libxul.so!mozilla::ThreadEventTarget::Dispatch(already_AddRefed<nsIRunnable>, unsigned int) [ThreadEventTarget.cpp:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 101 + 0x23]
[task 2020-12-08T22:05:06.041Z] 22:05:06 INFO - rbx = 0x0000000000000000 rbp = 0x00007fc5b717c8b0
[task 2020-12-08T22:05:06.042Z] 22:05:06 INFO - rsp = 0x00007fc5b717c850 r12 = 0x00007fc5b717c908
[task 2020-12-08T22:05:06.042Z] 22:05:06 INFO - r13 = 0x00007fc5b717c960 r14 = 0x00007fc5b717c870
[task 2020-12-08T22:05:06.042Z] 22:05:06 INFO - r15 = 0x00007fc5b51fd1b0 rip = 0x00007fc5c309c703
[task 2020-12-08T22:05:06.042Z] 22:05:06 INFO - Found by: call frame info
[task 2020-12-08T22:05:06.042Z] 22:05:06 INFO - 3 libxul.so!nsThread::Dispatch(already_AddRefed<nsIRunnable>, unsigned int) [nsThread.cpp:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 707 + 0x29]
[task 2020-12-08T22:05:06.042Z] 22:05:06 INFO - rbx = 0x00007fc5b717c8c0 rbp = 0x00007fc5b717c8f0
[task 2020-12-08T22:05:06.043Z] 22:05:06 INFO - rsp = 0x00007fc5b717c8c0 r12 = 0x00007fc5b717c908
[task 2020-12-08T22:05:06.043Z] 22:05:06 INFO - r13 = 0x00007fc5b717c960 r14 = 0x0000000000000000
[task 2020-12-08T22:05:06.043Z] 22:05:06 INFO - r15 = 0x00007fc5b70c6640 rip = 0x00007fc5c30a40e8
[task 2020-12-08T22:05:06.043Z] 22:05:06 INFO - Found by: call frame info
[task 2020-12-08T22:05:06.043Z] 22:05:06 INFO - 4 libxul.so!nsIEventTarget::Dispatch(nsIRunnable*, unsigned int) [nsIEventTarget.h: : 41 + 0x3a]
[task 2020-12-08T22:05:06.043Z] 22:05:06 INFO - rbx = 0x00007fc5b70c65f0 rbp = 0x00007fc5b717c940
[task 2020-12-08T22:05:06.043Z] 22:05:06 INFO - rsp = 0x00007fc5b717c900 r12 = 0x00007fc5b717c908
[task 2020-12-08T22:05:06.044Z] 22:05:06 INFO - r13 = 0x00007fc5b717c960 r14 = 0x0000000000000000
[task 2020-12-08T22:05:06.044Z] 22:05:06 INFO - r15 = 0x00007fc5b717c900 rip = 0x00007fc5c303e8a6
[task 2020-12-08T22:05:06.044Z] 22:05:06 INFO - Found by: call frame info
[task 2020-12-08T22:05:06.044Z] 22:05:06 INFO - 5 libxul.so!TimerThread::PostTimerEvent(already_AddRefed<nsTimerImpl>) [TimerThread.cpp:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 733 + 0x12]
[task 2020-12-08T22:05:06.044Z] 22:05:06 INFO - rbx = 0x00007fc5b51fd1b0 rbp = 0x00007fc5b717c9b0
[task 2020-12-08T22:05:06.044Z] 22:05:06 INFO - rsp = 0x00007fc5b717c950 r12 = 0x00007fc5bdd9d5f0
[task 2020-12-08T22:05:06.044Z] 22:05:06 INFO - r13 = 0x00007fc5b717c960 r14 = 0x00007fc5bdd9d5b0
[task 2020-12-08T22:05:06.045Z] 22:05:06 INFO - r15 = 0x00007fc5b717c9e8 rip = 0x00007fc5c309fbb7
[task 2020-12-08T22:05:06.045Z] 22:05:06 INFO - Found by: call frame info
[task 2020-12-08T22:05:06.045Z] 22:05:06 INFO - 6 libxul.so!TimerThread::Run() [TimerThread.cpp:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 417 + 0x1b]
[task 2020-12-08T22:05:06.045Z] 22:05:06 INFO - rbx = 0x00007fc5b70af3d0 rbp = 0x00007fc5b717ca30
[task 2020-12-08T22:05:06.045Z] 22:05:06 INFO - rsp = 0x00007fc5b717c9c0 r12 = 0x00007fc5bdd9d5b0
[task 2020-12-08T22:05:06.045Z] 22:05:06 INFO - r13 = 0x0000000000000000 r14 = 0x00007fc5b717c9e8
[task 2020-12-08T22:05:06.045Z] 22:05:06 INFO - r15 = 0x00007fc5bdd9d638 rip = 0x00007fc5c309f4be
[task 2020-12-08T22:05:06.046Z] 22:05:06 INFO - Found by: call frame info
[task 2020-12-08T22:05:06.046Z] 22:05:06 INFO - 7 libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 1200 + 0xe]
[task 2020-12-08T22:05:06.046Z] 22:05:06 INFO - rbx = 0x00007fc5b717ca88 rbp = 0x00007fc5b717cb30
[task 2020-12-08T22:05:06.046Z] 22:05:06 INFO - rsp = 0x00007fc5b717ca40 r12 = 0x00007fc5b70c63e0
[task 2020-12-08T22:05:06.046Z] 22:05:06 INFO - r13 = 0x0000000000000000 r14 = 0x00007fc5b70c6310
[task 2020-12-08T22:05:06.046Z] 22:05:06 INFO - r15 = 0x000004815c8be05a rip = 0x00007fc5c30a58ca
[task 2020-12-08T22:05:06.046Z] 22:05:06 INFO - Found by: call frame info
[task 2020-12-08T22:05:06.051Z] 22:05:06 INFO - 8 libxul.so!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 548 + 0xc]
[task 2020-12-08T22:05:06.051Z] 22:05:06 INFO - rbx = 0x0000000000000000 rbp = 0x00007fc5b717cb60
[task 2020-12-08T22:05:06.052Z] 22:05:06 INFO - rsp = 0x00007fc5b717cb40 r12 = 0x00007fc5b717cb78
[task 2020-12-08T22:05:06.052Z] 22:05:06 INFO - r13 = 0x00007fc5b70c80e0 r14 = 0x00007fc5b717cb47
[task 2020-12-08T22:05:06.053Z] 22:05:06 INFO - r15 = 0x00007fc5b70c6310 rip = 0x00007fc5c30a9bff
[task 2020-12-08T22:05:06.053Z] 22:05:06 INFO - Found by: call frame info
[task 2020-12-08T22:05:06.054Z] 22:05:06 INFO - 9 libxul.so!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 302 + 0xa]
[task 2020-12-08T22:05:06.054Z] 22:05:06 INFO - rbx = 0x00007fc5b717cc68 rbp = 0x00007fc5b717cbb0
[task 2020-12-08T22:05:06.055Z] 22:05:06 INFO - rsp = 0x00007fc5b717cb70 r12 = 0x00007fc5b717cb78
[task 2020-12-08T22:05:06.055Z] 22:05:06 INFO - r13 = 0x00007fc5b70c80e0 r14 = 0x00007fc5b70c80c0
[task 2020-12-08T22:05:06.056Z] 22:05:06 INFO - r15 = 0x00007fc5b70c6310 rip = 0x00007fc5c36ea324
[task 2020-12-08T22:05:06.056Z] 22:05:06 INFO - Found by: call frame info
[task 2020-12-08T22:05:06.057Z] 22:05:06 INFO - 10 libxul.so!MessageLoop::RunInternal() [message_loop.cc:840349cabe2f7e724539ab1b7c50a992f77af0d5 : 334 + 0x17]
[task 2020-12-08T22:05:06.058Z] 22:05:06 INFO - rbx = 0x00007fc5b717cc68 rbp = 0x00007fc5b717cbf0
[task 2020-12-08T22:05:06.059Z] 22:05:06 INFO - rsp = 0x00007fc5b717cbc0 r12 = 0x00007fc5b717cc68
[task 2020-12-08T22:05:06.059Z] 22:05:06 INFO - r13 = 0x00007fc5b717cc60 r14 = 0x00007fc5b717cc00
[task 2020-12-08T22:05:06.060Z] 22:05:06 INFO - r15 = 0x00007fc5b70c6358 rip = 0x00007fc5c3693b05
[task 2020-12-08T22:05:06.060Z] 22:05:06 INFO - Found by: call frame info

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Severity: normal → S3
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

I had a look at the stack trace, and it seem an event gets dispatched to the cacheIOThread after shutdown (so after we stopped processing such events) thus triggering the assertion here. The stack trace shows this coming from a timer.
Looking at the call graph it seems like the one place we do this is from CacheStorageService::Notify.
We should add a shutdown check to that place as well as make sure the timer is properly cancelled at shutdown (though it looks like it is?)

Blocks: necko-cache
Status: REOPENED → NEW
Priority: P5 → P2
Whiteboard: [necko-triaged]
Assignee: nobody → acreskey

We will no longer dispatch timer events to the cacheIOThread after shutdown as they would not be proccessed (and trigger an assertion in debug builds).

Pushed by acreskey@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/9283768cde81 Intermittent Assertion failure: mInsideLoop in CacheIOThread.cpp r=valentin,necko-reviewers
Status: NEW → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → FIXED
Target Milestone: --- → 121 Branch
See Also: → 1862623
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: