Closed Bug 1693968 Opened 4 years ago Closed 4 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_window_postMessage.html (finished) | application timed out after 370 seconds with no output

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=330595682&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aX19mP3OR1Sk1j0h9vttuQ/runs/0/artifacts/public/logs/live_backing.log


[task 2021-02-20T10:21:52.967Z] 10:21:52     INFO - TEST-OK | http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_window_postMessage.html | took 1089ms
[task 2021-02-20T10:21:52.982Z] 10:21:52     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/workspace/obj-build/dist/include/mozilla/ipc/ProtocolUtils.h:299
[task 2021-02-20T10:21:52.998Z] 10:21:52     INFO - GECKO(11917) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-20T10:21:52.999Z] 10:21:52     INFO - GECKO(11917) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-20T10:21:53.038Z] 10:21:53     INFO - TEST-START | Shutdown
[task 2021-02-20T10:21:53.038Z] 10:21:53     INFO - Passed:  2965
[task 2021-02-20T10:21:53.038Z] 10:21:53     INFO - Failed:  0
[task 2021-02-20T10:21:53.038Z] 10:21:53     INFO - Todo:    0
[task 2021-02-20T10:21:53.038Z] 10:21:53     INFO - Mode:    e10s
[task 2021-02-20T10:21:53.038Z] 10:21:53     INFO - Slowest: 66142ms - http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_tabs_permissions.html
[task 2021-02-20T10:21:53.038Z] 10:21:53     INFO - SimpleTest FINISHED
[task 2021-02-20T10:21:53.039Z] 10:21:53     INFO - TEST-INFO | Ran 1 Loops
[task 2021-02-20T10:21:53.039Z] 10:21:53     INFO - SimpleTest FINISHED
[task 2021-02-20T10:21:53.174Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:181
[task 2021-02-20T10:21:53.182Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:181
[task 2021-02-20T10:21:53.203Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:181
[task 2021-02-20T10:21:53.288Z] 10:21:53     INFO - GECKO(11917) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2021-02-20T10:21:53.389Z] 10:21:53     INFO - GECKO(11917) | [Child 16994, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-20T10:21:53.409Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-20T10:21:53.410Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-20T10:21:53.426Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-20T10:21:53.427Z] 10:21:53     INFO - GECKO(11917) | [Child 16994, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4380
[task 2021-02-20T10:21:53.443Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-20T10:21:53.444Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-20T10:21:53.604Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:181
[task 2021-02-20T10:21:53.701Z] 10:21:53     INFO - GECKO(11917) | [Parent 11917, 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 2021-02-20T10:21:53.737Z] 10:21:53     INFO - GECKO(11917) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-20T10:21:53.747Z] 10:21:53     INFO - GECKO(11917) | [Child 12025, Main Thread] WARNING: Finishing incremental GC in progress during CC: file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3301
[task 2021-02-20T10:21:53.762Z] 10:21:53     INFO - GECKO(11917) | [2021-02-20T10:21:53Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2021-02-20T10:21:53.764Z] 10:21:53     INFO - GECKO(11917) | [2021-02-20T10:21:53Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2021-02-20T10:21:54.488Z] 10:21:54     INFO - GECKO(11917) | [Child 12025, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-20T10:21:54.544Z] 10:21:54     INFO - GECKO(11917) | [Child 12025, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4380
[task 2021-02-20T10:21:54.882Z] 10:21:54     INFO - GECKO(11917) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-20T10:21:54.897Z] 10:21:54     INFO - GECKO(11917) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-20T10:21:54.993Z] 10:21:54     INFO - GECKO(11917) | [Child 17064, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-20T10:21:55.009Z] 10:21:55     INFO - GECKO(11917) | [Child 17019, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-20T10:21:55.024Z] 10:21:55     INFO - GECKO(11917) | [Child 17040, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-20T10:21:55.033Z] 10:21:55     INFO - GECKO(11917) | [Child 17064, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4380
[task 2021-02-20T10:21:55.048Z] 10:21:55     INFO - GECKO(11917) | [Child 17019, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4380
[task 2021-02-20T10:21:55.063Z] 10:21:55     INFO - GECKO(11917) | [Child 17040, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4380
[task 2021-02-20T10:21:55.100Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.000002s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.100Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.000550s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.100Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.000570s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.100Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.000631s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.100Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.000641s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.105Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.000669s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.105Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.000676s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.105Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: cache: '0.000694s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.105Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: sdb: '0.000702s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.106Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: ls: '0.000709s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.107Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.001047s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.108Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.001059s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.108Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.011279s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.109Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.011346s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.110Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.011357s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.111Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: idb: '0.011403s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.112Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: cache: '0.011727s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.112Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: sdb: '0.011743s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.113Z] 10:21:55     INFO - GECKO(11917) | [Parent 11917, IPDL Background] WARNING: ls: '0.011750s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-20T10:21:55.576Z] 10:21:55     INFO - GECKO(11917) | [Child 12023, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-20T10:21:55.636Z] 10:21:55     INFO - GECKO(11917) | [Child 12023, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4380
[task 2021-02-20T10:21:55.821Z] 10:21:55     INFO - GECKO(11917) | 1613816515820	Marionette	TRACE	Received observer notification xpcom-will-shutdown
[task 2021-02-20T10:21:55.828Z] 10:21:55     INFO - GECKO(11917) | 1613816515822	Marionette	INFO	Stopped listening on port 2828
[task 2021-02-20T10:21:55.829Z] 10:21:55     INFO - GECKO(11917) | 1613816515822	Marionette	DEBUG	Marionette stopped listening
[task 2021-02-20T10:21:55.845Z] 10:21:55     INFO - GECKO(11917) | *** WIFI GEO: shutdown called
[task 2021-02-20T10:22:08.497Z] 10:22:08     INFO - GECKO(11917) | [Parent 11917, Main Thread] WARNING: NS_ENSURE_TRUE(mReady) failed: file /builds/worker/checkouts/gecko/xpfe/appshell/nsWindowMediator.cpp:161
[task 2021-02-20T10:22:08.498Z] 10:22:08     INFO - GECKO(11917) | JavaScript error: resource:///modules/sessionstore/SessionStore.jsm, line 5069: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIWindowMediator.getEnumerator]
[task 2021-02-20T10:22:28.384Z] 10:22:28     INFO - GECKO(11917) | [Child 16938, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
[task 2021-02-20T10:22:28.385Z] 10:22:28     INFO - GECKO(11917) | [Child 16938, Main Thread] WARNING: '!ipcActor->SendUpdateChildScalars(scalarsToSend)', file /builds/worker/checkouts/gecko/toolkit/components/telemetry/core/ipc/TelemetryIPCAccumulator.cpp:287
[task 2021-02-20T10:22:28.386Z] 10:22:28     INFO - GECKO(11917) | [Child 16938, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
[task 2021-02-20T10:22:28.387Z] 10:22:28     INFO - GECKO(11917) | [Child 16938, Main Thread] WARNING: '!ipcActor->SendRecordDiscardedData(discardedData)', file /builds/worker/checkouts/gecko/toolkit/components/telemetry/core/ipc/TelemetryIPCAccumulator.cpp:298
[task 2021-02-20T10:22:59.509Z] 10:22:59     INFO - GECKO(11917) | XPCOM_MEM_BLOAT_LOG: /tmp/tmpa1kbf0.mozrunner/runtests_leaks.log
[task 2021-02-20T10:22:59.510Z] 10:22:59     INFO - GECKO(11917) | Writing to log: /tmp/tmpa1kbf0.mozrunner/runtests_leaks.log
[task 2021-02-20T10:23:00.513Z] 10:23:00     INFO - GECKO(11917) | Hit MOZ_CRASH(Shutdown hanging after all known phases and workers finished.) at /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:233
[task 2021-02-20T10:23:00.534Z] 10:23:00     INFO - GECKO(11917) | #01: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:204]
[task 2021-02-20T10:23:00.534Z] 10:23:00     INFO - GECKO(11917) | #02: ??? [/lib/x86_64-linux-gnu/libpthread.so.0 + 0x76db]
[task 2021-02-20T10:23:00.534Z] 10:23:00     INFO - GECKO(11917) | #03: clone [/lib/x86_64-linux-gnu/libc.so.6 + 0x121a3f]
[task 2021-02-20T10:23:00.534Z] 10:23:00     INFO - GECKO(11917) | #04: ??? (???:???)
[task 2021-02-20T10:23:00.534Z] 10:23:00     INFO - GECKO(11917) | ExceptionHandler::GenerateDump cloned child 17096
[task 2021-02-20T10:23:00.534Z] 10:23:00     INFO - GECKO(11917) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2021-02-20T10:23:00.534Z] 10:23:00     INFO - GECKO(11917) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2021-02-20T10:23:00.690Z] 10:23:00     INFO - GECKO(11917) | [Child 16938, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
[task 2021-02-20T10:23:00.690Z] 10:23:00     INFO - GECKO(11917) | [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2021-02-20T10:29:10.706Z] 10:29:10     INFO - Buffered messages finished
[task 2021-02-20T10:29:10.708Z] 10:29:10    ERROR - TEST-UNEXPECTED-TIMEOUT | http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_window_postMessage.html (finished) | application timed out after 370 seconds with no output
[task 2021-02-20T10:29:10.709Z] 10:29:10    ERROR - Force-terminating active process(es).
[task 2021-02-20T10:29:10.710Z] 10:29:10     INFO - Determining child pids from psutil...
[task 2021-02-20T10:29:10.757Z] 10:29:10     INFO - []
[task 2021-02-20T10:29:10.758Z] 10:29:10     INFO - ==> process 11917 launched child process 11937```
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.