Closed Bug 1522243 Opened 5 years ago Closed 4 years ago

Intermittent PID 2384 | Assertion failure: parentFound, at /builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerManagerService.cpp:186

Categories

(Core :: DOM: Service Workers, defect, P2)

defect

Tracking

()

RESOLVED FIXED
mozilla76
Tracking Status
firefox76 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered])

Attachments

(1 file)

Filed by: rmaries [at] mozilla.com

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

https://queue.taskcluster.net/v1/task/JjBH1WFYTI-82_y5hjCAfw/runs/0/artifacts/public/logs/live_backing.log

08:08:01 INFO - TEST-START | /background-fetch/content-security-policy.https.window.html
08:08:01 INFO - PID 2384 | ++DOMWINDOW == 3 (0x1269c2400) [pid = 2390] [serial = 3] [outer = 0x126906400]
08:08:01 INFO - PID 2384 | [Child 2387, Main Thread] WARNING: NS_ENSURE_TRUE(domReturn) failed: file /builds/worker/workspace/build/src/dom/base/nsGlobalWindowOuter.cpp, line 7147
08:08:01 INFO - PID 2384 | [Child 2390, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 559
08:08:01 INFO - PID 2384 | ++DOCSHELL 0x1143da800 == 1 [pid = 2389] [id = {b0002b02-fe35-a84e-8063-54e895fe7ab1}]
08:08:01 INFO - PID 2384 | ++DOMWINDOW == 1 (0x11c207c00) [pid = 2389] [serial = 1] [outer = 0x0]
08:08:01 INFO - PID 2384 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
08:08:01 INFO - PID 2384 | [Child 2388, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 869
08:08:01 INFO - PID 2384 | ++DOMWINDOW == 2 (0x11c209800) [pid = 2389] [serial = 2] [outer = 0x11c207c00]
08:08:01 INFO - PID 2384 | [Child 2388, Main Thread] WARNING: '!gThread', file /builds/worker/workspace/build/src/xpcom/threads/nsTimerImpl.cpp, line 299
08:08:01 INFO - PID 2384 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/mf/zg1ht33x4fldvvc3rzp6tm1r00000x/T/tmpQVDx5F.mozrunner/runtests_leaks_1794_tab_pid2391.log
08:08:01 INFO - PID 2384 | --DOCSHELL 0x11ffd9800 == 0 [pid = 2388] [id = {1510336d-8796-e54d-a1b9-20d259458734}]
08:08:01 INFO - PID 2384 | --DOMWINDOW == 3 (0x127d06400) [pid = 2388] [serial = 1] [outer = 0x0] [url = https://web-platform.test:8443/background-fetch/abort.https.window.html]
08:08:01 INFO - PID 2384 | --DOMWINDOW == 2 (0x127d07c00) [pid = 2388] [serial = 2] [outer = 0x0] [url = about:blank]
08:08:01 INFO - PID 2384 | --DOMWINDOW == 1 (0x128805c00) [pid = 2388] [serial = 3] [outer = 0x0] [url = about:blank]
08:08:01 INFO - PID 2384 | --DOMWINDOW == 0 (0x12880c400) [pid = 2388] [serial = 4] [outer = 0x0] [url = https://web-platform.test:8443/background-fetch/abort.https.window.html]
08:08:01 INFO - PID 2384 | nsStringStats
08:08:01 INFO - PID 2384 | => mAllocCount: 9595
08:08:01 INFO - PID 2384 | => mReallocCount: 0
08:08:01 INFO - PID 2384 | => mFreeCount: 9595
08:08:01 INFO - PID 2384 | => mShareCount: 9582
08:08:01 INFO - PID 2384 | => mAdoptCount: 541
08:08:01 INFO - PID 2384 | => mAdoptFreeCount: 557
08:08:01 INFO - PID 2384 | => Process ID: 2388, Thread ID: 140735109251840
08:08:01 INFO - PID 2384 | ++DOMWINDOW == 3 (0x11c2c2000) [pid = 2389] [serial = 3] [outer = 0x11c207c00]
08:08:01 INFO - PID 2384 | [Parent 2384, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/netwerk/url-classifier/UrlClassifierCommon.cpp, line 122
08:08:01 INFO - PID 2384 | ++DOMWINDOW == 4 (0x11c2c8800) [pid = 2389] [serial = 4] [outer = 0x11c207c00]
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 559
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 559
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 559
08:08:02 INFO - PID 2384 | [Parent 2384, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/netwerk/url-classifier/UrlClassifierCommon.cpp, line 122
08:08:02 INFO - PID 2384 | [Parent 2384, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/netwerk/url-classifier/AsyncUrlChannelClassifier.cpp, line 751
08:08:02 INFO - Closing window 8589934593
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: '!window', file /builds/worker/workspace/build/src/dom/cache/CacheStorage.cpp, line 559
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: A runnable was posted to a worker that is already shutting down!: file /builds/worker/workspace/build/src/dom/workers/WorkerPrivate.cpp, line 1356
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: NS_ENSURE_TRUE(global) failed: file /builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerRegistrationImpl.cpp, line 106
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: A runnable was posted to a worker that is already shutting down!: file /builds/worker/workspace/build/src/dom/workers/WorkerPrivate.cpp, line 1356
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: NS_ENSURE_TRUE(global) failed: file /builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerRegistrationImpl.cpp, line 142
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/workspace/build/src/widget/cocoa/nsAppShell.mm, line 722
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: A runnable was posted to a worker that is already shutting down!: file /builds/worker/workspace/build/src/dom/workers/WorkerPrivate.cpp, line 1356
08:08:02 INFO - PID 2384 | [Child 2389, Main Thread] WARNING: Failed to dispatch offline status change event!: file /builds/worker/workspace/build/src/dom/workers/WorkerPrivate.cpp, line 1808
08:08:02 INFO - PID 2384 | Assertion failure: parentFound, at /builds/worker/workspace/build/src/dom/serviceworkers/ServiceWorkerManagerService.cpp:186
08:08:02 WARNING - Traceback (most recent call last):
08:08:02 WARNING - File "/Users/cltbld/tasks/task_1548258803/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/base.py", line 162, in run_test
08:08:02 WARNING - result = self.do_test(test)
08:08:02 WARNING - File "/Users/cltbld/tasks/task_1548258803/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 693, in do_test
08:08:02 WARNING - assertion_count = self.protocol.asserts.get()
08:08:02 WARNING - File "/Users/cltbld/tasks/task_1548258803/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 350, in get
08:08:02 WARNING - with self.marionette.using_context(self.marionette.CONTEXT_CHROME):
08:08:02 WARNING - File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in enter
08:08:02 WARNING - return self.gen.next()
08:08:02 WARNING - File "/Users/cltbld/tasks/task_1548258803/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1493, in using_context
08:08:02 WARNING - key="value")
08:08:02 WARNING - File "/Users/cltbld/tasks/task_1548258803/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
08:08:02 WARNING - return func(args, kwargs)
08:08:02 WARNING - File "/Users/cltbld/tasks/task_1548258803/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 753, in _send_message
08:08:02 WARNING - raise errors.InvalidSessionIdException("Please start a session")
08:08:02 WARNING - InvalidSessionIdException: Please start a session
08:08:02 WARNING -
08:08:02 INFO - mozcrash Copy/paste: /Users/cltbld/tasks/task_1548258803/build/macosx64-minidump_stackwalk /var/folders/mf/zg1ht33x4fldvvc3rzp6tm1r00000x/T/tmpQVDx5F.mozrunner/minidumps/30760BF7-4D64-46CC-B725-6D22B498A964.dmp /Users/cltbld/tasks/task_1548258803/build/symbols
08:08:22 INFO - mozcrash Saved minidump as /Users/cltbld/tasks/task_1548258803/build/blobber_upload_dir/30760BF7-4D64-46CC-B725-6D22B498A964.dmp
08:08:22 INFO - mozcrash Saved app info as /Users/cltbld/tasks/task_1548258803/build/blobber_upload_dir/30760BF7-4D64-46CC-B725-6D22B498A964.extra
08:08:23 INFO - PROCESS-CRASH | /background-fetch/content-security-policy.https.window.html | application crashed [@ mozilla::dom::ServiceWorkerManagerService::PropagateUnregister(unsigned long long, mozilla::ipc::PrincipalInfo const&, nsTSubstring<char16_t> const&)]
08:08:23 INFO - Crash dump filename: /var/folders/mf/zg1ht33x4fldvvc3rzp6tm1r00000x/T/tmpQVDx5F.mozrunner/minidumps/30760BF7-4D64-46CC-B725-6D22B498A964.dmp
08:08:23 INFO - Operating system: Mac OS X
08:08:23 INFO - 10.10.5 14F27
08:08:23 INFO - CPU: amd64
08:08:23 INFO - family 6 model 69 stepping 1
08:08:23 INFO - 4 CPUs
08:08:23 INFO -
08:08:23 INFO - GPU: UNKNOWN
08:08:23 INFO -
08:08:23 INFO - Crash reason: EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
08:08:23 INFO - Crash address: 0x0
08:08:23 INFO - Process uptime: 10 seconds
08:08:23 INFO -
08:08:23 INFO - Thread 17 (crashed)
08:08:23 INFO - 0 XUL!mozilla::dom::ServiceWorkerManagerService::PropagateUnregister(unsigned long long, mozilla::ipc::PrincipalInfo const&, nsTSubstring<char16_t> const&) [ServiceWorkerManagerService.cpp:cac13d592b66535ee7abbf05a71952f21654dc21 : 186 + 0x0]
08:08:23 INFO - rax = 0x000000010dbf3a2e rdx = 0x00007fff732af1f8
08:08:23 INFO - rcx = 0x00000001060f46b0 rbx = 0x000000010d88fe3a
08:08:23 INFO - rsi = 0x0000740000007400 rdi = 0x0000730000007403
08:08:23 INFO - rbp = 0x00000001192417e0 rsp = 0x0000000119241720
08:08:23 INFO - r8 = 0x00000001192416d0 r9 = 0x0000000119242000
08:08:23 INFO - r10 = 0x00007fff8a61b3ef r11 = 0x00007fff8a61b3c0
08:08:23 INFO - r12 = 0x0000000000000000 r13 = 0x0000000000000000
08:08:23 INFO - r14 = 0x0000000119241748 r15 = 0x00000001258fed60
08:08:23 INFO - rip = 0x000000010a141727
08:08:23 INFO - Found by: given as instruction pointer in context
08:08:23 INFO - 1 XUL!mozilla::dom::(anonymous namespace)::UnregisterServiceWorkerCallback::Run() [ServiceWorkerManagerParent.cpp:cac13d592b66535ee7abbf05a71952f21654dc21 : 100 + 0xe]
08:08:23 INFO - rbp = 0x0000000119241880 rsp = 0x00000001192417f0
08:08:23 INFO - rip = 0x000000010a140dba
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 2 XUL!mozilla::dom::(anonymous namespace)::CheckPrincipalWithCallbackRunnable::Run() [ServiceWorkerManagerParent.cpp:cac13d592b66535ee7abbf05a71952f21654dc21 : 139 + 0x6]
08:08:23 INFO - rbp = 0x00000001192418a0 rsp = 0x0000000119241890
08:08:23 INFO - rip = 0x000000010a15fce7
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 3 XUL!nsThread::ProcessNextEvent(bool, bool
) [nsThread.cpp:cac13d592b66535ee7abbf05a71952f21654dc21 : 1160 + 0x6]
08:08:23 INFO - rbp = 0x0000000119241db0 rsp = 0x00000001192418b0
08:08:23 INFO - rip = 0x00000001068170cb
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 4 XUL!NS_ProcessNextEvent(nsIThread
, bool) [nsThreadUtils.cpp:cac13d592b66535ee7abbf05a71952f21654dc21 : 468 + 0xd]
08:08:23 INFO - rbp = 0x0000000119241de0 rsp = 0x0000000119241dc0
08:08:23 INFO - rip = 0x000000010681aee8
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 5 XUL!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate
) [MessagePump.cpp:cac13d592b66535ee7abbf05a71952f21654dc21 : 333 + 0xd]
08:08:23 INFO - rbp = 0x0000000119241e30 rsp = 0x0000000119241df0
08:08:23 INFO - rip = 0x0000000106f128bd
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 6 XUL!MessageLoop::Run() [message_loop.cc:cac13d592b66535ee7abbf05a71952f21654dc21 : 308 + 0x5]
08:08:23 INFO - rbp = 0x0000000119241e60 rsp = 0x0000000119241e40
08:08:23 INFO - rip = 0x0000000106eb3655
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 7 XUL!nsThread::ThreadFunc(void*) [nsThread.cpp:cac13d592b66535ee7abbf05a71952f21654dc21 : 449 + 0x8]
08:08:23 INFO - rbp = 0x0000000119241eb0 rsp = 0x0000000119241e70
08:08:23 INFO - rip = 0x0000000106813b15
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 8 libnss3.dylib!_pt_root [ptthread.c:cac13d592b66535ee7abbf05a71952f21654dc21 : 201 + 0x3]
08:08:23 INFO - rbp = 0x0000000119241ef0 rsp = 0x0000000119241ec0
08:08:23 INFO - rip = 0x000000010656cb10
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 9 libsystem_pthread.dylib + 0x405a
08:08:23 INFO - rbp = 0x0000000119241f10 rsp = 0x0000000119241f00
08:08:23 INFO - rip = 0x00007fff8a61e05a
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 10 libsystem_pthread.dylib + 0x3fd7
08:08:23 INFO - rbp = 0x0000000119241f50 rsp = 0x0000000119241f20
08:08:23 INFO - rip = 0x00007fff8a61dfd7
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 11 libsystem_pthread.dylib + 0x13ed
08:08:23 INFO - rbp = 0x0000000119241f78 rsp = 0x0000000119241f60
08:08:23 INFO - rip = 0x00007fff8a61b3ed
08:08:23 INFO - Found by: previous frame's frame pointer
08:08:23 INFO - 12 libnss3.dylib + 0x16c9f0
08:08:23 INFO - rsp = 0x0000000119242030 rip = 0x000000010656c9f0
08:08:23 INFO - Found by: stack scanning
08:08:23 INFO -

There are 32 failures in the last 2 days.
:overholt , could you please take a look?

Flags: needinfo?(overholt)
Whiteboard: [stockwell needswork]

Maybe Eden can take a look.

Flags: needinfo?(overholt) → needinfo?(echuang)

It is not possible for bug 1520282 to affect OS X tests.

From the retriggers shown by comment 7, it looks to me like this assertion failure started with bug 1521801.

Flags: needinfo?(gbrown)

That's why I asked. However, the failures in comment 7 do not have the assertion line failure and I was not sure if that means they are separate issues or the same?

Nathan can you please take a look at the failures in comment 7?

Also, for those failures, bug 1471718 has been reopened.

Flags: needinfo?(nfroyd)

This looks like stuff deep inside service workers, which is not my forte. asuth?

Flags: needinfo?(nfroyd) → needinfo?(bugmail)

The assertion is unsound on 1 of its 2 call-paths:

  1. Safe: ServiceWorkerManagerParent::RecvPropagateUnregister synchronously calls ServiceWorkerManagerService::PropagateUnregister. The actor that we're receiving the call from must still exist and be alive.
  2. Unsafe: ServiceWorkerManagerParent::RecvUnregister creates a UnregisterServiceWorkerCallback that invokes PropagateUnregister in a future turn of the evnt loop following the CheckPrincipalWithCallbackRunnable it creates bouncing to the main thread and back again. By the time it gets back, the parent actor corresponding to the process may have been destroyed.

This is a sanity-check assertion that's present in all of the propagate calls. The logic wants to make sure it doesn't redundantly propagate the information back to the process that's telling us the information, which begged the check of whether the parent is in the list. It's a nice check but only safe to do synchronously from within the IPC call itself.

Assignee: nobody → bugmail
Status: NEW → ASSIGNED
Flags: needinfo?(echuang)
Flags: needinfo?(bugmail)

:asuth Do you have any updates?
In the last 7 days, there have been 88 failures.
Recent failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=225992368&repo=mozilla-inbound&lineNumber=60162

Thank you!

Flags: needinfo?(bugmail)

In the last 7 days there has been 1 single failure.

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered]
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered]

No failures since February the 11th.

Priority: -- → P2

(In reply to Andrew Sutherland [:asuth] (he/him) from comment #13)

The assertion is unsound on 1 of its 2 call-paths:

  1. Safe: ServiceWorkerManagerParent::RecvPropagateUnregister synchronously calls ServiceWorkerManagerService::PropagateUnregister. The actor that we're receiving the call from must still exist and be alive.
  2. Unsafe: ServiceWorkerManagerParent::RecvUnregister creates a UnregisterServiceWorkerCallback that invokes PropagateUnregister in a future turn of the evnt loop following the CheckPrincipalWithCallbackRunnable it creates bouncing to the main thread and back again. By the time it gets back, the parent actor corresponding to the process may have been destroyed.

This is a sanity-check assertion that's present in all of the propagate calls. The logic wants to make sure it doesn't redundantly propagate the information back to the process that's telling us the information, which begged the check of whether the parent is in the list. It's a nice check but only safe to do synchronously from within the IPC call itself.

So should we remove the check and can safely ignore this case? Or should we always verify, if there is a parent at the beginning before propagating anything and in case just do nothing and return (to better cover the 2. call-path)?

This has been mooted by parent-intercept being enabled, because we no longer use these actors, but we should still potentially fix this.

So should we remove the check and can safely ignore this case? Or should we always verify, if there is a parent at the beginning before propagating anything and in case just do nothing and return (to better cover the 2. call-path)?

Yes, we can remove the assertion, it was unsound.

Assignee: bugmail → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(bugmail)
Assignee: nobody → ssengupta
Attachment #9132812 - Attachment description: Bug 1522243 - Needless assertion 'parentFound' removed from ServiceWorkerManagerService.cpp r=asuth → Bug 1522243 - Unreliable assertion 'parentFound' removed from ServiceWorkerManagerService.cpp r=asuth
Attachment #9132812 - Attachment description: Bug 1522243 - Unreliable assertion 'parentFound' removed from ServiceWorkerManagerService.cpp r=asuth → Bug 1522243 - Debug-only flag 'parentFound' and related assertion removed from ServiceWorkerManagerService.cpp r=asuth
Attachment #9132812 - Attachment description: Bug 1522243 - Debug-only flag 'parentFound' and related assertion removed from ServiceWorkerManagerService.cpp r=asuth → Bug 1522243 - Use of debug-only flag 'parentFound' and related assertion removed from methods in ServiceWorkerManagerService.cpp r=asuth
Pushed by aiakab@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/cf5a9e5612b5
Use of debug-only flag 'parentFound' and related assertion removed from methods in ServiceWorkerManagerService.cpp r=dom-workers-and-storage-reviewers,perry
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla76
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: