Open Bug 1533753 Opened 9 months ago Updated 3 months ago

Intermittent new-serviceworker leakcheck | default 18988 bytes leaked (ChannelEventQueue, ChannelWrapper::ChannelWrapperStub, CondVar, ConsoleReportCollector, CookieSettings, ...)

Categories

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

defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])

#[markdown(off)]
Filed by: shindli [at] mozilla.com

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

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

[task 2019-03-08T15:02:16.547Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.549Z] 15:02:16 INFO - nsTraceRefcnt::DumpStatistics: 2304 entries
[task 2019-03-08T15:02:16.550Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 ChannelEventQueue
[task 2019-03-08T15:02:16.551Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 ChannelWrapper::ChannelWrapperStub
[task 2019-03-08T15:02:16.552Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 5 CondVar
[task 2019-03-08T15:02:16.553Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 ConsoleReportCollector
[task 2019-03-08T15:02:16.554Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 CookieSettings
[task 2019-03-08T15:02:16.555Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 3 DataStorage
[task 2019-03-08T15:02:16.556Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 HttpBaseChannel
[task 2019-03-08T15:02:16.556Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 HttpChannelParent
[task 2019-03-08T15:02:16.558Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 HttpChannelParentListener
[task 2019-03-08T15:02:16.559Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 IdlePeriod
[task 2019-03-08T15:02:16.559Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 LazyIdleThread
[task 2019-03-08T15:02:16.560Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 LoadContext
[task 2019-03-08T15:02:16.561Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 LoadInfo
[task 2019-03-08T15:02:16.562Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 19 Mutex
[task 2019-03-08T15:02:16.563Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 PHttpChannelParent
[task 2019-03-08T15:02:16.564Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 PollableEvent
[task 2019-03-08T15:02:16.565Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 ReentrantMonitor
[task 2019-03-08T15:02:16.566Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 RequestContextService
[task 2019-03-08T15:02:16.566Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 Service
[task 2019-03-08T15:02:16.567Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 ServiceWorkerInterceptController
[task 2019-03-08T15:02:16.567Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 ThirdPartyUtil
[task 2019-03-08T15:02:16.568Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 ThreadEventTarget
[task 2019-03-08T15:02:16.569Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 ThreadTargetSink
[task 2019-03-08T15:02:16.569Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 2 WeakReference<WebExtensionPolicy>
[task 2019-03-08T15:02:16.570Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 nsAuthURLParser
[task 2019-03-08T15:02:16.570Z] 15:02:16 INFO - TEST-INFO | leakcheck | default leaked 1 nsCategoryObserver

Test run ended with dom/serviceworkers/test/test_xslt.html

[task 2019-03-08T15:00:50.838Z] 15:00:50 INFO - GECKO(3365) | [Parent 3365, Main Thread] ###!!! ASSERTION: 1 dynamic atom(s) with non-zero refcount: http://mochi.test:8888: 'nonZeroRefcountAtomsCount == 0', file /builds/worker/workspace/build/src/xpcom/ds/nsAtomTable.cpp, line 446
[task 2019-03-08T15:02:16.338Z] 15:02:16 INFO - GECKO(3365) | #01: nsAtomTable::GC(GCKind) [xpcom/threads/Mutex.h:168]
[task 2019-03-08T15:02:16.338Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.340Z] 15:02:16 INFO - GECKO(3365) | #02: NS_ShutdownAtomTable() [xpcom/ds/nsAtomTable.cpp:485]
[task 2019-03-08T15:02:16.340Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.341Z] 15:02:16 INFO - GECKO(3365) | #03: mozilla::ShutdownXPCOM(nsIServiceManager*) [xpcom/build/XPCOMInit.cpp:803]
[task 2019-03-08T15:02:16.341Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.342Z] 15:02:16 INFO - GECKO(3365) | #04: ScopedXPCOMStartup::~ScopedXPCOMStartup() [toolkit/xre/nsAppRunner.cpp:1238]
[task 2019-03-08T15:02:16.342Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.343Z] 15:02:16 INFO - GECKO(3365) | #05: mozilla::UniquePtr<ScopedXPCOMStartup, mozilla::DefaultDelete<ScopedXPCOMStartup> >::reset(ScopedXPCOMStartup*) [memory/mozalloc/mozalloc.h:151]
[task 2019-03-08T15:02:16.344Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.345Z] 15:02:16 INFO - GECKO(3365) | #06: XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:4718]
[task 2019-03-08T15:02:16.345Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.345Z] 15:02:16 INFO - GECKO(3365) | #07: XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:4766]
[task 2019-03-08T15:02:16.346Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.346Z] 15:02:16 INFO - GECKO(3365) | #08: _fini
[task 2019-03-08T15:02:16.346Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.347Z] 15:02:16 INFO - GECKO(3365) | #09: libc.so.6 + 0x20830
[task 2019-03-08T15:02:16.347Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.348Z] 15:02:16 INFO - GECKO(3365) | #10: _fini
[task 2019-03-08T15:02:16.348Z] 15:02:16 INFO -
[task 2019-03-08T15:02:16.349Z] 15:02:16 INFO - GECKO(3365) | Leaked URLs:
[task 2019-03-08T15:02:16.349Z] 15:02:16 INFO - GECKO(3365) | http://mochi.test:8888/tests/dom/serviceworkers/test/fetch/plugin/foo.txt
[task 2019-03-08T15:02:16.350Z] 15:02:16 INFO - GECKO(3365) | http://mochi.test:8888/tests/dom/serviceworkers/test/fetch/plugin/foo.txt
[task 2019-03-08T15:02:16.350Z] 15:02:16 INFO - GECKO(3365) | http://mochi.test:8888/tests/dom/serviceworkers/test/fetch/plugin/plugins.html
[task 2019-03-08T15:02:16.351Z] 15:02:16 INFO - GECKO(3365) | http://mochi.test:8888/tests/dom/serviceworkers/test/fetch/plugin/plugins.html
[task 2019-03-08T15:02:16.351Z] 15:02:16 INFO - GECKO(3365) | http://mochi.test:8888/tests/dom/serviceworkers/test/fetch/plugin/plugins.html
[task 2019-03-08T15:02:16.352Z] 15:02:16 INFO - GECKO(3365) | http://mochi.test:8888/

Summary: Intermittent leakcheck | default 18988 bytes leaked (ChannelEventQueue, ChannelWrapper::ChannelWrapperStub, CondVar, ConsoleReportCollector, CookieSettings, ...) → Intermittent new-serviceworker leakcheck | default 18988 bytes leaked (ChannelEventQueue, ChannelWrapper::ChannelWrapperStub, CondVar, ConsoleReportCollector, CookieSettings, ...)

There are 28 total failures in the last 7 days on linux64 debug: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-19&endday=2019-04-26&tree=trunk&bug=1533753

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=242873628&repo=mozilla-inbound&lineNumber=12541

[task 2019-04-26T13:46:44.217Z] 13:46:44 INFO - TEST-START | dom/serviceworkers/test/test_xslt.html
[task 2019-04-26T13:47:27.986Z] 13:47:27 INFO - TEST-UNEXPECTED-FAIL | leakcheck | default 18996 bytes leaked (ChannelEventQueue, ChannelWrapper::ChannelWrapperStub, CondVar, ConsoleReportCollector, CookieSettings, ...)
[task 2019-04-26T13:47:27.986Z] 13:47:27 INFO -
[task 2019-04-26T13:47:27.986Z] 13:47:27 INFO - leakcheck | Processing leak log file /tmp/tmpf5O41f.mozrunner/runtests_leaks_tab_pid3281.log
[task 2019-04-26T13:47:27.987Z] 13:47:27 INFO -
[task 2019-04-26T13:47:27.987Z] 13:47:27 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 3281
[task 2019-04-26T13:47:27.988Z] 13:47:27 INFO -
[task 2019-04-26T13:47:27.988Z] 13:47:27 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2019-04-26T13:47:27.989Z] 13:47:27 INFO - | | Per-Inst Leaked| Total Rem|
[task 2019-04-26T13:47:27.990Z] 13:47:27 INFO - 0 |TOTAL | 43 0| 18761 0|
[task 2019-04-26T13:47:27.990Z] 13:47:27 INFO -
[task 2019-04-26T13:47:27.991Z] 13:47:27 INFO - nsTraceRefcnt::DumpStatistics: 399 entries
[task 2019-04-26T13:47:27.991Z] 13:47:27 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2019-04-26T13:47:27.992Z] 13:47:27 INFO - leakcheck | Processing leak log file /tmp/tmpf5O41f.mozrunner/runtests_leaks_tab_pid2996.log
[task 2019-04-26T13:47:27.992Z] 13:47:27 INFO -
[task 2019-04-26T13:47:27.993Z] 13:47:27 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 2996
[task 2019-04-26T13:47:27.993Z] 13:47:27 INFO -
[task 2019-04-26T13:47:27.994Z] 13:47:27 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2019-04-26T13:47:27.994Z] 13:47:27 INFO - | | Per-Inst Leaked| Total Rem|
[task 2019-04-26T13:47:27.995Z] 13:47:27 INFO - 0 |TOTAL | 33 0| 7090639 0|
[task 2019-04-26T13:47:28.003Z] 13:47:28 INFO -
[task 2019-04-26T13:47:28.004Z] 13:47:28 INFO - nsTraceRefcnt::DumpStatistics: 1316 entries
[task 2019-04-26T13:47:28.005Z] 13:47:28 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2019-04-26T13:47:28.006Z] 13:47:28 INFO - runtests.py | Running tests: end.
[task 2019-04-26T13:47:28.062Z] 13:47:28 INFO - Buffered messages finished
[task 2019-04-26T13:47:28.063Z] 13:47:28 INFO - Running manifest: dom/smil/test/mochitest.ini
[task 2019-04-26T13:47:28.172Z] 13:47:28 INFO - Setting pipeline to PAUSED ...
[task 2019-04-26T13:47:28.172Z] 13:47:28 INFO - Pipeline is PREROLLING ...
[task 2019-04-26T13:47:28.176Z] 13:47:28 INFO - Pipeline is PREROLLED ...
[task 2019-04-26T13:47:28.177Z] 13:47:28 INFO - Setting pipeline to PLAYING ...
[task 2019-04-26T13:47:28.177Z] 13:47:28 INFO - New clock: GstSystemClock
[task 2019-04-26T13:47:28.213Z] 13:47:28 INFO - Got EOS from element "pipeline0".
[task 2019-04-26T13:47:28.214Z] 13:47:28 INFO - Execution ended after 0:00:00.033505544
[task 2019-04-26T13:47:28.214Z] 13:47:28 INFO - Setting pipeline to PAUSED ...
[task 2019-04-26T13:47:28.214Z] 13:47:28 INFO - Setting pipeline to READY ...
[task 2019-04-26T13:47:28.214Z] 13:47:28 INFO - (gst-launch-1.0:3335): GStreamer-CRITICAL **: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2019-04-26T13:47:28.214Z] 13:47:28 INFO - Setting pipeline to NULL ...
[task 2019-04-26T13:47:28.215Z] 13:47:28 INFO - Freeing pipeline ...
[task 2019-04-26T13:47:28.573Z] 13:47:28 INFO - pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2019-04-26T13:47:28.856Z] 13:47:28 INFO - MochitestServer : launching [u'/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-f', '/builds/worker/workspace/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpLKHKKv.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2019-04-26T13:47:28.857Z] 13:47:28 INFO - runtests.py | Server pid: 3357
[task 2019-04-26T13:47:28.933Z] 13:47:28 INFO - runtests.py | Websocket server pid: 3361
[task 2019-04-26T13:47:29.056Z] 13:47:29 INFO - [3357, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, NS_ERROR_UNEXPECTED) failed with result 0x80004005: file /builds/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 1026
[task 2019-04-26T13:47:29.072Z] 13:47:29 INFO - runtests.py | SSL tunnel pid: 3371
[task 2019-04-26T13:47:29.255Z] 13:47:29 INFO - Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-04-26T13:47:29.255Z] 13:47:29 INFO - [3357, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/workspace/build/src/dom/media/CubebUtils.cpp, line 385
[task 2019-04-26T13:47:29.277Z] 13:47:29 INFO - runtests.py | Running with scheme: http
[task 2019-04-26T13:47:29.278Z] 13:47:29 INFO - runtests.py | Running with e10s: True
[task 2019-04-26T13:47:29.279Z] 13:47:29 INFO - runtests.py | Running with serviceworker_e10s: True
[task 2019-04-26T13:47:29.280Z] 13:47:29 INFO - runtests.py | Running with socketprocess_e10s: False
[task 2019-04-26T13:47:29.281Z] 13:47:29 INFO - runtests.py | Running tests: start.
[task 2019-04-26T13:47:29.282Z] 13:47:29 INFO -
[task 2019-04-26T13:47:29.303Z] 13:47:29 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpLKHKKv.mozrunner
[task 2019-04-26T13:47:29.385Z] 13:47:29 INFO - runtests.py | Application pid: 3382
[task 2019-04-26T13:47:29.385Z] 13:47:29 INFO - TEST-INFO | started process GECKO(3382)
[task 2019-04-26T13:47:29.421Z] 13:47:29 INFO - GECKO(3382) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpLKHKKv.mozrunner/runtests_leaks.log

Andrew, could you please assign this to someone?

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

Thanks. We'll get to this after we land our parent intercept work (bug 1231208).

Flags: needinfo?(overholt)
Priority: P5 → P2
You need to log in before you can comment on or make changes to this bug.