Intermittent test_csp.html, test_dataURLWorker.html | Assertion count {1,2} is greater than expected range (Didn't know about this one!: 'mChildWorkers.Contains(aChildWorker)', Mismatched busy count mods!: 'aIncrease || mBusyCount') and a leak

RESOLVED FIXED in mozilla22

Status

()

Core
DOM: Workers
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: RyanVM, Assigned: khuey)

Tracking

({assertion, intermittent-failure})

unspecified
mozilla22
x86_64
Linux
assertion, intermittent-failure
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(2 attachments)

(Reporter)

Description

5 years ago
https://tbpl.mozilla.org/php/getParsedLog.php?id=20444669&tree=Mozilla-Inbound&full=1

builder: mozilla-inbound_fedora64-debug_test-mochitest-4
slave: talos-r3-fed64-029

19:07:21     INFO -  711 INFO TEST-START | /tests/dom/workers/test/test_csp.html
19:07:21     INFO -  ++DOMWINDOW == 35 (0x2450758) [serial = 186] [outer = 0x44a1388]
19:07:21     INFO -  712 INFO TEST-PASS | /tests/dom/workers/test/test_csp.html | Loading data:something
19:07:21     INFO -  JavaScript error: http://mochi.test:8888/tests/dom/workers/test/test_csp.js, line 38: Failed to load script: data:application/javascript;base64,ZHVtcCgnaGVsbG8gd29ybGQnKQo= (nsresult = 0x805e0006)
19:07:21     INFO -  713 INFO TEST-PASS | /tests/dom/workers/test/test_csp.html | Loading data:something
19:07:21     INFO -  WARNING: No principal to execute JS with: file ../../../../dom/src/jsurl/nsJSProtocolHandler.cpp, line 159
19:07:21     INFO -  714 INFO TEST-PASS | /tests/dom/workers/test/test_csp.html | Loading data:something
19:07:21     INFO -  715 INFO TEST-END | /tests/dom/workers/test/test_csp.html | finished in 202ms
19:07:21     INFO -  716 INFO TEST-PASS | /tests/dom/workers/test/test_csp.html | Loading data:something
19:07:21     INFO -  ++DOMWINDOW == 36 (0x3006078) [serial = 187] [outer = 0x44a1388]
19:07:21     INFO -  ###!!! ASSERTION: Didn't know about this one!: 'mChildWorkers.Contains(aChildWorker)', file ../../../dom/workers/WorkerPrivate.cpp, line 3301
19:07:42     INFO -  mozilla::dom::workers::RuntimeService::UnregisterWorker(JSContext*, mozilla::dom::workers::WorkerPrivate*) [dom/workers/RuntimeService.cpp:907]
19:07:42     INFO -  mozilla::dom::workers::RuntimeService::RegisterWorker(JSContext*, mozilla::dom::workers::WorkerPrivate*) [dom/workers/RuntimeService.cpp:820]
19:07:42     INFO -  Worker::ConstructInternal [dom/workers/Worker.cpp:138]
19:07:42     INFO -  js::InvokeConstructorKernel(JSContext*, JS::CallArgs) [js/src/jscntxtinlines.h:328]
19:07:42     INFO -  js::Interpret(JSContext*, js::StackFrame*, js::InterpMode) [js/src/jsinterp.cpp:2358]
19:07:42     INFO -  js::RunScript(JSContext*, js::StackFrame*) [js/src/jsinterp.cpp:340]
19:07:42     INFO -  js::InvokeKernel(JSContext*, JS::CallArgs, js::MaybeConstruct) [js/src/jsinterp.cpp:397]
19:07:42     INFO -  js::Invoke(JSContext*, JS::Value const&, JS::Value const&, unsigned int, JS::Value*, JS::Value*) [js/src/jsinterp.cpp:430]
19:07:42     INFO -  JS_CallFunctionValue(JSContext*, JSObject*, JS::Value, unsigned int, JS::Value*, JS::Value*) [js/src/jsapi.cpp:5040]
19:07:42     INFO -  mozilla::dom::workers::EventListenerManager::DispatchEvent(JSContext*, mozilla::dom::workers::EventTarget const&, JSObject*, mozilla::ErrorResult&) const [dom/workers/EventListenerManager.cpp:422]
19:07:42     INFO -  mozilla::dom::EventTargetBinding_workers::dispatchEvent [obj-firefox/dom/bindings/EventTargetBinding.cpp:618]
19:07:42     INFO -  mozilla::dom::EventTargetBinding_workers::genericMethod [obj-firefox/dom/bindings/EventTargetBinding.cpp:655]
19:07:42     INFO -  js::InvokeKernel(JSContext*, JS::CallArgs, js::MaybeConstruct) [js/src/jscntxtinlines.h:328]
19:07:42     INFO -  js::Invoke(JSContext*, JS::Value const&, JS::Value const&, unsigned int, JS::Value*, JS::Value*) [js/src/jsinterp.cpp:430]
19:07:42     INFO -  JS_CallFunctionName(JSContext*, JSObject*, char const*, unsigned int, JS::Value*, JS::Value*) [js/src/jsapi.cpp:5699]
19:07:42     INFO -  mozilla::dom::workers::events::DispatchEventToTarget(JSContext*, JSObject*, JSObject*, bool*) [dom/workers/Events.cpp:1080]
19:07:42     INFO -  MessageEventRunnable::WorkerRun [dom/workers/WorkerPrivate.cpp:822]
19:07:42     INFO -  mozilla::dom::workers::WorkerRunnable::Run() [dom/workers/WorkerPrivate.cpp:1619]
19:07:42     INFO -  mozilla::dom::workers::WorkerPrivate::DoRunLoop(JSContext*) [dom/workers/WorkerPrivate.cpp:2732]
19:07:42     INFO -  WorkerThreadRunnable::Run [dom/workers/RuntimeService.cpp:511]
19:07:42     INFO -  nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:627]
19:07:42     INFO -  NS_ProcessNextEvent_P(nsIThread*, bool) [obj-firefox/xpcom/build/nsThreadUtils.cpp:238]
19:07:42     INFO -  nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:264]
19:07:42     INFO -  _pt_root [nsprpub/pr/src/pthreads/ptthread.c:194]
19:07:42     INFO -  libpthread.so.0 + 0x6a3a
19:07:42     INFO -  libc.so.6 + 0xddf3d
19:07:42     INFO -  ###!!! ASSERTION: Mismatched busy count mods!: 'aIncrease || mBusyCount', file ../../../dom/workers/WorkerPrivate.cpp, line 2084
19:07:42     INFO -  mozilla::dom::workers::WorkerRunnable::Run() [dom/workers/WorkerPrivate.cpp:1619]
19:07:42     INFO -  mozilla::dom::workers::WorkerPrivate::DoRunLoop(JSContext*) [dom/workers/WorkerPrivate.cpp:2732]
19:07:42     INFO -  WorkerThreadRunnable::Run [dom/workers/RuntimeService.cpp:511]
19:07:42     INFO -  nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:627]
19:07:42     INFO -  NS_ProcessNextEvent_P(nsIThread*, bool) [obj-firefox/xpcom/build/nsThreadUtils.cpp:238]
19:07:42     INFO -  nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:264]
19:07:42     INFO -  _pt_root [nsprpub/pr/src/pthreads/ptthread.c:194]
19:07:42     INFO -  libpthread.so.0 + 0x6a3a
19:07:42     INFO -  libc.so.6 + 0xddf3d
19:07:42     INFO -  717 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/workers/test/test_csp.html | Assertion count 2 is greater than expected range 0-0 assertions.
(Reporter)

Comment 1

5 years ago
^ and a leak.

19:14:29  WARNING -  TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 8290 bytes during test execution
19:14:29  WARNING -  TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 2 instances of CondVar with size 32 bytes each (64 bytes total)
19:14:29  WARNING -  TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 2 instances of DOMBindingBase with size 56 bytes each (112 bytes total)
19:14:29  WARNING -  TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 1 instance of HttpBaseChannel with size 728 bytes
19:14:29  WARNING -  TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 1 instance of MemoryReporter_StorageSQLite with size 24 bytes
19:14:29  WARNING -  TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked 6 instances of Mutex with size 24 bytes each (144 bytes total)
Summary: Intermittent test_csp.html | Assertion count 2 is greater than expected range (Didn't know about this one!: 'mChildWorkers.Contains(aChildWorker)', Mismatched busy count mods!: 'aIncrease || mBusyCount') → Intermittent test_csp.html | Assertion count 2 is greater than expected range (Didn't know about this one!: 'mChildWorkers.Contains(aChildWorker)', Mismatched busy count mods!: 'aIncrease || mBusyCount') and a leak
(Reporter)

Comment 2

5 years ago
Another version.
https://tbpl.mozilla.org/php/getParsedLog.php?id=20441280&tree=Mozilla-Inbound&full=1#error0
Summary: Intermittent test_csp.html | Assertion count 2 is greater than expected range (Didn't know about this one!: 'mChildWorkers.Contains(aChildWorker)', Mismatched busy count mods!: 'aIncrease || mBusyCount') and a leak → Intermittent test_csp.html | Assertion count {1,2} is greater than expected range (Didn't know about this one!: 'mChildWorkers.Contains(aChildWorker)', Mismatched busy count mods!: 'aIncrease || mBusyCount') and a leak
(Reporter)

Comment 3

5 years ago
Regression from bug 587251?
Blocks: 587251
> 815       if (NS_FAILED(NS_GetNavigatorAppName(mNavigatorStrings.mAppName)) ||
> 816           NS_FAILED(NS_GetNavigatorAppVersion(mNavigatorStrings.mAppVersion)) ||
> 817           NS_FAILED(NS_GetNavigatorPlatform(mNavigatorStrings.mPlatform)) ||
> 818           NS_FAILED(NS_GetNavigatorUserAgent(mNavigatorStrings.mUserAgent))) {
> 819         JS_ReportError(aCx, "Failed to load navigator strings!");
> 820         UnregisterWorker(aCx, aWorkerPrivate);
> 821         return false;
> 822       }

So we failed to get the navigator strings?  How did that happen!?
(In reply to Ryan VanderMeulen [:RyanVM] from comment #3)
> Regression from bug 587251?

Seems like the most likely candidate.
Comment hidden (Treeherder Robot)
(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #4)
> > 815       if (NS_FAILED(NS_GetNavigatorAppName(mNavigatorStrings.mAppName)) ||
> > 816           NS_FAILED(NS_GetNavigatorAppVersion(mNavigatorStrings.mAppVersion)) ||
> > 817           NS_FAILED(NS_GetNavigatorPlatform(mNavigatorStrings.mPlatform)) ||
> > 818           NS_FAILED(NS_GetNavigatorUserAgent(mNavigatorStrings.mUserAgent))) {
> > 819         JS_ReportError(aCx, "Failed to load navigator strings!");
> > 820         UnregisterWorker(aCx, aWorkerPrivate);
> > 821         return false;
> > 822       }
> 
> So we failed to get the navigator strings?  How did that happen!?

Line 820 will be executed only on the main thread while line 907 will be executed only on worker threads!
I've caught this in record and replay.
Assignee: nobody → khuey
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
> msg = "Loading data:something";
> worker = new Worker("data:application/javascript;base64,ZHVtcCgnaGVsbG8gd29ybGQnKQo=");
> worker = new Worker("javascript:dump(123);");
>
> SimpleTest.waitForExplicitFinish();

After bug 587251, new Worker("data:...") will throw immediately instead of dispatching an error event. So SimpleTest.waitForExplicitFinish() will not be called and the test page will be gone.
If the postMessage handler is executed after that, AddChildWorker() will fail and it will cause the assertions because UnregisterWorker() will be called without adding the child and increasing the mod count.
Created attachment 722965 [details] [diff] [review]
Part 1: Fix workers

The underlying problem here is that we're now running a sync event loop during WorkerPrivate::Create, so its possible that the parent worker begins to shut down during that call.  Then registration fails and a bunch of other things go wrong.
Attachment #722965 - Flags: review?(bent.mozilla)
Created attachment 722966 [details] [diff] [review]
Part 2: Tweak tests
Attachment #722966 - Flags: review?
Comment on attachment 722966 [details] [diff] [review]
Part 2: Tweak tests

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

grumble
Attachment #722966 - Flags: review? → review?(bent.mozilla)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
https://tbpl.mozilla.org/php/getParsedLog.php?id=20513222&tree=Firefox
Summary: Intermittent test_csp.html | Assertion count {1,2} is greater than expected range (Didn't know about this one!: 'mChildWorkers.Contains(aChildWorker)', Mismatched busy count mods!: 'aIncrease || mBusyCount') and a leak → Intermittent test_csp.html, test_dataURLWorker.html | Assertion count {1,2} is greater than expected range (Didn't know about this one!: 'mChildWorkers.Contains(aChildWorker)', Mismatched busy count mods!: 'aIncrease || mBusyCount') and a leak
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment on attachment 722965 [details] [diff] [review]
Part 1: Fix workers

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

Thanks!

::: dom/workers/WorkerPrivate.cpp
@@ +2623,5 @@
>                                                       getter_AddRefs(channel));
> +
> +    // Now that we've spun the loop there's no guarantee that our parent is
> +    // still alive.  We may have received control messages initiating shutdown.
> + 

Nit: Whitespace

@@ +2640,5 @@
> +
> +      nsIChannel* rawChannel;
> +      channel.forget(&rawChannel);
> +      // If this fails we accept the leak.
> +      NS_ProxyRelease(mainThread, rawChannel);

Nit: Go ahead and warn though.

@@ +3313,2 @@
>    {
> +	  Status currentStatus;

Nit: Tabs here.
Attachment #722965 - Flags: review?(bent.mozilla) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/4c0d6d844a4e
https://hg.mozilla.org/integration/mozilla-inbound/rev/13a8acb57b35
Comment on attachment 722966 [details] [diff] [review]
Part 2: Tweak tests

Got r+ in real life.
Attachment #722966 - Flags: review?(bent.mozilla) → review+
https://hg.mozilla.org/mozilla-central/rev/4c0d6d844a4e
https://hg.mozilla.org/mozilla-central/rev/13a8acb57b35
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla22
Comment hidden (Treeherder Robot)
You need to log in before you can comment on or make changes to this bug.