1474041 - Intermittent toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | leaked 1 window(s) until shutdown [url = about:blank]

Reporter

Description

•

6 years ago

treeherder

Filed by: rgurzau [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=186925353&repo=autoland https://queue.taskcluster.net/v1/task/CONIZq6nTOG5EaSWf2oYDQ/runs/0/artifacts/public/logs/live_backing.log [task 2018-07-06T23:27:55.722Z] 23:27:55 INFO - TEST-START | Shutdown [task 2018-07-06T23:27:55.723Z] 23:27:55 INFO - Browser Chrome Test Summary [task 2018-07-06T23:27:55.725Z] 23:27:55 INFO - Passed: 493 [task 2018-07-06T23:27:55.727Z] 23:27:55 INFO - Failed: 0 [task 2018-07-06T23:27:55.729Z] 23:27:55 INFO - Todo: 0 [task 2018-07-06T23:27:55.730Z] 23:27:55 INFO - Mode: e10s [task 2018-07-06T23:27:55.731Z] 23:27:55 INFO - *** End BrowserChrome Test Results *** [task 2018-07-06T23:27:56.916Z] 23:27:56 INFO - GECKO(4506) | --DOCSHELL 0xd2f50800 == 5 [pid = 4506] [id = {62023d42-e7f2-47a9-868c-8cadb853f0b7}] [task 2018-07-06T23:27:56.916Z] 23:27:56 INFO - GECKO(4506) | --DOCSHELL 0xe78a0000 == 4 [pid = 4506] [id = {88d00fb7-86cf-41ba-803b-0d54538bead3}] [task 2018-07-06T23:27:56.916Z] 23:27:56 INFO - GECKO(4506) | --DOCSHELL 0xdf2d2c00 == 3 [pid = 4506] [id = {1b0efe4d-7c35-480c-9092-853b1a7ac663}] [task 2018-07-06T23:27:56.916Z] 23:27:56 INFO - GECKO(4506) | --DOCSHELL 0xde556400 == 2 [pid = 4506] [id = {3b6484d3-91b6-4e23-8932-b7dd5d092f8e}] [task 2018-07-06T23:27:56.916Z] 23:27:56 INFO - GECKO(4506) | --DOCSHELL 0xe4dd6800 == 1 [pid = 4506] [id = {7e64b63f-63e8-4acc-ac15-e9abbc60522c}] [task 2018-07-06T23:27:57.013Z] 23:27:57 INFO - GECKO(4506) | [Child 4659, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 794 [task 2018-07-06T23:27:57.016Z] 23:27:57 INFO - GECKO(4506) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost [task 2018-07-06T23:27:57.025Z] 23:27:57 INFO - GECKO(4506) | [Child 4636, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 794 [task 2018-07-06T23:27:57.026Z] 23:27:57 INFO - GECKO(4506) | [Child 4636, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 794 [task 2018-07-06T23:27:57.087Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 794 [task 2018-07-06T23:27:57.237Z] 23:27:57 INFO - GECKO(4506) | [Child 4556, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 794 [task 2018-07-06T23:27:57.588Z] 23:27:57 INFO - GECKO(4506) | --DOCSHELL 0xe2ed2c00 == 0 [pid = 4599] [id = {5ed113f5-8604-48c1-93ed-cde66be321cd}] [task 2018-07-06T23:27:57.626Z] 23:27:57 INFO - GECKO(4506) | nsStringStats [task 2018-07-06T23:27:57.626Z] 23:27:57 INFO - GECKO(4506) | => mAllocCount: 39258 [task 2018-07-06T23:27:57.626Z] 23:27:57 INFO - GECKO(4506) | => mReallocCount: 2278 [task 2018-07-06T23:27:57.626Z] 23:27:57 INFO - GECKO(4506) | => mFreeCount: 39258 [task 2018-07-06T23:27:57.627Z] 23:27:57 INFO - GECKO(4506) | => mShareCount: 44790 [task 2018-07-06T23:27:57.628Z] 23:27:57 INFO - GECKO(4506) | => mAdoptCount: 4666 [task 2018-07-06T23:27:57.629Z] 23:27:57 INFO - GECKO(4506) | => mAdoptFreeCount: 4682 [task 2018-07-06T23:27:57.630Z] 23:27:57 INFO - GECKO(4506) | => Process ID: 4636, Thread ID: 4147631872 [task 2018-07-06T23:27:57.689Z] 23:27:57 INFO - GECKO(4506) | nsStringStats [task 2018-07-06T23:27:57.689Z] 23:27:57 INFO - GECKO(4506) | => mAllocCount: 57996 [task 2018-07-06T23:27:57.689Z] 23:27:57 INFO - GECKO(4506) | => mReallocCount: 2995 [task 2018-07-06T23:27:57.690Z] 23:27:57 INFO - GECKO(4506) | => mFreeCount: 57996 [task 2018-07-06T23:27:57.690Z] 23:27:57 INFO - GECKO(4506) | => mShareCount: 112786 [task 2018-07-06T23:27:57.691Z] 23:27:57 INFO - GECKO(4506) | => mAdoptCount: 4672 [task 2018-07-06T23:27:57.691Z] 23:27:57 INFO - GECKO(4506) | => mAdoptFreeCount: 4732 [task 2018-07-06T23:27:57.691Z] 23:27:57 INFO - GECKO(4506) | => Process ID: 4659, Thread ID: 4146665216 [task 2018-07-06T23:27:57.890Z] 23:27:57 INFO - GECKO(4506) | --DOMWINDOW == 1 (0xf714dbd0) [pid = 4599] [serial = 51] [outer = (nil)] [url = about:blank] [task 2018-07-06T23:27:57.890Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:27:57.890Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:27:57.890Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:27:57.890Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:27:57.890Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:27:57.890Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:27:57.890Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:27:57.890Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:27:57.891Z] 23:27:57 INFO - GECKO(4506) | [Child 4599, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:27:57.892Z] 23:27:57 INFO - GECKO(4506) | --DOMWINDOW == 0 (0xe2ed4400) [pid = 4599] [serial = 52] [outer = (nil)] [url = about:blank] [task 2018-07-06T23:27:58.032Z] 23:27:58 INFO - GECKO(4506) | nsStringStats [task 2018-07-06T23:27:58.032Z] 23:27:58 INFO - GECKO(4506) | => mAllocCount: 39435 [task 2018-07-06T23:27:58.032Z] 23:27:58 INFO - GECKO(4506) | => mReallocCount: 2259 [task 2018-07-06T23:27:58.032Z] 23:27:58 INFO - GECKO(4506) | => mFreeCount: 39435 [task 2018-07-06T23:27:58.032Z] 23:27:58 INFO - GECKO(4506) | => mShareCount: 35085 [task 2018-07-06T23:27:58.034Z] 23:27:58 INFO - GECKO(4506) | => mAdoptCount: 5152 [task 2018-07-06T23:27:58.034Z] 23:27:58 INFO - GECKO(4506) | => mAdoptFreeCount: 5164 [task 2018-07-06T23:27:58.034Z] 23:27:58 INFO - GECKO(4506) | => Process ID: 4599, Thread ID: 4147582720 [task 2018-07-06T23:27:58.122Z] 23:27:58 INFO - GECKO(4506) | nsStringStats [task 2018-07-06T23:27:58.123Z] 23:27:58 INFO - GECKO(4506) | => mAllocCount: 38097 [task 2018-07-06T23:27:58.125Z] 23:27:58 INFO - GECKO(4506) | => mReallocCount: 2335 [task 2018-07-06T23:27:58.125Z] 23:27:58 INFO - GECKO(4506) | => mFreeCount: 38097 [task 2018-07-06T23:27:58.126Z] 23:27:58 INFO - GECKO(4506) | => mShareCount: 58966 [task 2018-07-06T23:27:58.127Z] 23:27:58 INFO - GECKO(4506) | => mAdoptCount: 3206 [task 2018-07-06T23:27:58.130Z] 23:27:58 INFO - GECKO(4506) | => mAdoptFreeCount: 3234 [task 2018-07-06T23:27:58.131Z] 23:27:58 INFO - GECKO(4506) | => Process ID: 4556, Thread ID: 4147554048 [task 2018-07-06T23:27:58.200Z] 23:27:58 INFO - GECKO(4506) | 1530919678190 Marionette DEBUG Received observer notification xpcom-will-shutdown [task 2018-07-06T23:27:58.202Z] 23:27:58 INFO - GECKO(4506) | 1530919678191 Marionette INFO Stopped listening on port 2828 [task 2018-07-06T23:27:58.202Z] 23:27:58 INFO - GECKO(4506) | 1530919678192 Marionette DEBUG Remote service is inactive [task 2018-07-06T23:27:58.222Z] 23:27:58 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: NS_ENSURE_TRUE(mDB) failed: file /builds/worker/workspace/build/src/netwerk/cache/nsDiskCacheDeviceSQL.cpp, line 1422 [task 2018-07-06T23:27:58.260Z] 23:27:58 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /builds/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 794 [task 2018-07-06T23:27:59.362Z] 23:27:59 INFO - GECKO(4506) | --DOCSHELL 0xde55a000 == 0 [pid = 4506] [id = {63d50aff-2d25-4c98-9737-45d402a7a976}] [task 2018-07-06T23:27:59.363Z] 23:27:59 INFO - GECKO(4506) | --DOMWINDOW == 12 (0xd2f46400) [pid = 4506] [serial = 96] [outer = (nil)] [url = about:blank] [task 2018-07-06T23:28:00.093Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 11 (0xe78a0c00) [pid = 4506] [serial = 4] [outer = (nil)] [url = about:blank] [task 2018-07-06T23:28:00.114Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 10 (0xd7fd8000) [pid = 4506] [serial = 115] [outer = (nil)] [url = about:blank] [task 2018-07-06T23:28:00.114Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 9 (0xf7149710) [pid = 4506] [serial = 6] [outer = (nil)] [url = about:blank] [task 2018-07-06T23:28:00.132Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 8 (0xf7149120) [pid = 4506] [serial = 3] [outer = (nil)] [url = chrome://browser/content/browser.xul] [task 2018-07-06T23:28:00.134Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 7 (0xde5b37a0) [pid = 4506] [serial = 17] [outer = (nil)] [url = chrome://mochikit/content/browser-harness.xul] [task 2018-07-06T23:28:00.136Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 6 (0xd657b000) [pid = 4506] [serial = 18] [outer = (nil)] [url = about:blank] [task 2018-07-06T23:28:00.138Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 5 (0xde5b3080) [pid = 4506] [serial = 14] [outer = (nil)] [url = moz-extension://5ea6676b-5e0e-4a23-8873-d2d387fd1231/_generated_background_page.html] [task 2018-07-06T23:28:00.140Z] 23:28:00 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:28:00.143Z] 23:28:00 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:28:00.146Z] 23:28:00 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:28:00.148Z] 23:28:00 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:28:00.150Z] 23:28:00 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:28:00.152Z] 23:28:00 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:28:00.154Z] 23:28:00 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:28:00.156Z] 23:28:00 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:28:00.157Z] 23:28:00 INFO - GECKO(4506) | [Parent 4506, Main Thread] WARNING: '!mMainThread', file /builds/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 517 [task 2018-07-06T23:28:00.159Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 4 (0xde55fc00) [pid = 4506] [serial = 13] [outer = (nil)] [url = chrome://extensions/content/dummy.xul] [task 2018-07-06T23:28:00.160Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 3 (0xf714aed0) [pid = 4506] [serial = 10] [outer = (nil)] [url = chrome://extensions/content/dummy.xul] [task 2018-07-06T23:28:00.161Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 2 (0xf7148b30) [pid = 4506] [serial = 1] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html] [task 2018-07-06T23:28:00.162Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 1 (0xde562c00) [pid = 4506] [serial = 16] [outer = (nil)] [url = moz-extension://5ea6676b-5e0e-4a23-8873-d2d387fd1231/_generated_background_page.html] [task 2018-07-06T23:28:00.163Z] 23:28:00 INFO - GECKO(4506) | --DOMWINDOW == 0 (0xe78ab800) [pid = 4506] [serial = 5] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html] [task 2018-07-06T23:28:00.241Z] 23:28:00 INFO - GECKO(4506) | nsStringStats [task 2018-07-06T23:28:00.242Z] 23:28:00 INFO - GECKO(4506) | => mAllocCount: 232448 [task 2018-07-06T23:28:00.243Z] 23:28:00 INFO - GECKO(4506) | => mReallocCount: 21234 [task 2018-07-06T23:28:00.244Z] 23:28:00 INFO - GECKO(4506) | => mFreeCount: 232448 [task 2018-07-06T23:28:00.245Z] 23:28:00 INFO - GECKO(4506) | => mShareCount: 273690 [task 2018-07-06T23:28:00.245Z] 23:28:00 INFO - GECKO(4506) | => mAdoptCount: 7880 [task 2018-07-06T23:28:00.246Z] 23:28:00 INFO - GECKO(4506) | => mAdoptFreeCount: 8136 [task 2018-07-06T23:28:00.247Z] 23:28:00 INFO - GECKO(4506) | => Process ID: 4506, Thread ID: 4147885824 [task 2018-07-06T23:28:00.277Z] 23:28:00 INFO - TEST-INFO | Main app process: exit 0 [task 2018-07-06T23:28:00.278Z] 23:28:00 ERROR - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | leaked 1 window(s) until shutdown [url = about:blank]

Joel Maher ( :jmaher ) (UTC -8)

Comment 1

•

6 years ago

this reproduced in test-verify: https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=linux%20debug%20verify&tochange=e8c173a632a43ca26f2e0d7eb4ca362ece212ef4&fromchange=44861ed17925f75e8b2ef0109b5b0c655cccc95d&selectedJob=186967425 2/3 times and on the previous push it failed. (note: there is an extra tv-bf from a different test, so make sure to look at what was tested)

Whiteboard: [TV-bf pass:fail]

Joel Maher ( :jmaher ) (UTC -8)

Comment 2

•

6 years ago

:glandium, this looks to be caused by your changes in bug 1469088, can you take a look at this?

Blocks: 1469088

Flags: needinfo?(mh+mozilla)

Mike Hommey [:glandium]

Comment 3

•

6 years ago

How can that even be related? That changed nothing for linux debug builds.

Flags: needinfo?(mh+mozilla) → needinfo?(jmaher)

Joel Maher ( :jmaher ) (UTC -8)

Comment 4

•

6 years ago

after doing more retriggers on test-verify, it looks like it fails more frequently on the identified push: https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=linux%20debug%20verify&tochange=e8c173a632a43ca26f2e0d7eb4ca362ece212ef4&fromchange=44861ed17925f75e8b2ef0109b5b0c655cccc95d&selectedJob=187005683 Not sure why, but if bug 1469088 has nothing to do with linux builds and related linking, then this just just be a rare timing incident.

Flags: needinfo?(jmaher)

Comment hidden (Intermittent Failures Robot)

Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)

Comment 6

•

6 years ago

This test got added at the end of last week in bug 1347204.

Blocks: 1347204
No longer blocks: 1469088

Comment hidden (Intermittent Failures Robot)

Tim Nguyen :ntim

Updated

•

6 years ago

URL: https://bugzilla.mozilla.org/show_bug...

Tim Nguyen :ntim

Updated

•

6 years ago

URL: https://bugzilla.mozilla.org/show_bug...

See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1473920

Comment hidden (Intermittent Failures Robot)

Razvan Maries

Comment 56

•

5 years ago

There are 21 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-08-20&endday=2019-08-27&tree=trunk&bug=1474041

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=263517127&repo=autoland&lineNumber=39668

Jim, could you assign this to someone?

Flags: needinfo?(jmathies)

Whiteboard: [TV-bf pass:fail] → [TV-bf pass:fail][stockwell needwork:owner]

Jim Mathies [:jimm]

Comment 57

•

5 years ago

Appears to have recently regressed. Rob, did we change anything in theme code recently? We did some work for the color extension but looks that was in the extension vs. apis. Wondering if there's anything else we can think of that might have caused this to regress.

Flags: needinfo?(jmathies) → needinfo?(rob)

Comment hidden (Intermittent Failures Robot)

Andreea Pavel [:apavel]

Comment 59

•

5 years ago

Hi Jim, looks like Rob did not reply, can you please try someone else?

There are 25 total failures in the last 7 days and 63 in the last 30 on windows10-64-qr, windows10-64, linux64, linux64-ccov debug builds

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=265591786&repo=autoland&lineNumber=39948

[task 2019-09-08T11:43:26.780Z] 11:43:26 INFO - TEST-START | toolkit/components/extensions/test/browser/browser_ext_themes_warnings.js
[task 2019-09-08T11:43:26.799Z] 11:43:26 INFO - GECKO(9684) | monitorConsole | [0] did not match {"message":"Warning: attempting to write 6776 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.","errorMessage":null,"cssSelectors":null,"sourceName":null,"sourceLine":null,"lineNumber":null,"columnNumber":null,"category":null,"windowID":null,"isScriptError":false,"isConsoleEvent":false,"isWarning":false,"isException":false,"isStrict":false}
[task 2019-09-08T11:43:26.829Z] 11:43:26 INFO - GECKO(9684) | 1567943006825 addons.webextension.{c7673a66-fcf6-4ae4-b927-9756cf27d9b1} WARN Unrecognized theme property found: colors.such_property
[task 2019-09-08T11:43:26.855Z] 11:43:26 INFO - GECKO(9684) | monitorConsole | [0] matched {"message":"1567943006825\taddons.webextension.{c7673a66-fcf6-4ae4-b927-9756cf27d9b1}\tWARN\tUnrecognized theme property found: colors.such_property","errorMessage":null,"cssSelectors":null,"sourceName":null,"sourceLine":null,"lineNumber":null,"columnNumber":null,"category":null,"windowID":null,"isScriptError":false,"isConsoleEvent":false,"isWarning":false,"isException":false,"isStrict":false}
[task 2019-09-08T11:43:26.904Z] 11:43:26 INFO - GECKO(9684) | monitorConsole | [0] did not match {"message":"Warning: attempting to write 6856 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.","errorMessage":null,"cssSelectors":null,"sourceName":null,"sourceLine":null,"lineNumber":null,"columnNumber":null,"category":null,"windowID":null,"isScriptError":false,"isConsoleEvent":false,"isWarning":false,"isException":false,"isStrict":false}
[task 2019-09-08T11:43:26.923Z] 11:43:26 INFO - GECKO(9684) | 1567943006915 addons.webextension.{735a3580-47b6-486c-9e6f-71fee5331f01} WARN Unrecognized theme property found: images.such_property

[task 2019-09-08T11:43:37.949Z] 11:43:37 INFO - GECKO(9684) | [Parent 6300, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file z:/build/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-09-08T11:43:37.949Z] 11:43:37 INFO - GECKO(9684) | [Parent 6300, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file z:/build/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-09-08T11:43:37.949Z] 11:43:37 INFO - GECKO(9684) | nsStringStats
[task 2019-09-08T11:43:37.949Z] 11:43:37 INFO - GECKO(9684) | => mAllocCount: 288486
[task 2019-09-08T11:43:37.949Z] 11:43:37 INFO - GECKO(9684) | => mReallocCount: 2
[task 2019-09-08T11:43:37.949Z] 11:43:37 INFO - GECKO(9684) | => mFreeCount: 288486
[task 2019-09-08T11:43:37.950Z] 11:43:37 INFO - GECKO(9684) | => mShareCount: 350141
[task 2019-09-08T11:43:37.950Z] 11:43:37 INFO - GECKO(9684) | => mAdoptCount: 5811
[task 2019-09-08T11:43:37.950Z] 11:43:37 INFO - GECKO(9684) | => mAdoptFreeCount: 6249
[task 2019-09-08T11:43:37.950Z] 11:43:37 INFO - GECKO(9684) | => Process ID: 6300, Thread ID: 5352
[task 2019-09-08T11:43:38.016Z] 11:43:38 INFO - TEST-INFO | Main app process: exit 0
[task 2019-09-08T11:43:38.016Z] 11:43:38 ERROR - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | leaked 1 window(s) until shutdown [url = about:blank]
[task 2019-09-08T11:43:38.017Z] 11:43:38 ERROR - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | leaked 1 window(s) until shutdown [url = chrome://browser/content/browser.xhtml]
[task 2019-09-08T11:43:38.017Z] 11:43:38 INFO - TEST-INFO | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | windows(s) leaked: [pid = 6300] [serial = 63], [pid = 6300] [serial = 62]
[task 2019-09-08T11:43:38.018Z] 11:43:38 INFO - TEST-INFO | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | This test created 1 hidden window(s)
[task 2019-09-08T11:43:38.018Z] 11:43:38 INFO - TEST-INFO | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js | This test created 1 hidden docshell(s)
[task 2019-09-08T11:43:38.019Z] 11:43:38 INFO - TEST-INFO | toolkit/components/extensions/test/browser/browser_ext_management_themes.js | This test created 1 hidden window(s)
[task 2019-09-08T11:43:38.019Z] 11:43:38 INFO - TEST-INFO | toolkit/components/extensions/test/browser/browser_ext_management_themes.js | This test created 1 hidden docshell(s)

Flags: needinfo?(jmathies)

Comment hidden (Intermittent Failures Robot)

Rob Wu [:robwu]

Assignee

Comment 62

•

5 years ago

I haven't forgotten, but I cannot reproduce this locally, and there is nothing special in the logs either (well I found and filed two bugs, but they are probably not causing this issue - bug 1579943, bug 1579832).
The most unusual thing is that the log from treeherder does not contain the stack trace from bug 1579943 , which could either mean that the stack trace was discarded from the post-processed log (as the log entry is generated at the completion of the test), or that the browser window was not removed, somehow.

The test logic is similar to browser_ext_themes_ntp_colors.js, which has not caused any reports on BMO. The only difference is that the test from this bug creates and closes a new browser window. But the logic seems correct and shouldn't be causing leaks.

I'm keeping the ni on myself to investigate this further if I'm idle.

Flags: needinfo?(jmathies)

Andreea Pavel [:apavel]

Comment 63

•

5 years ago

Okay Rob, thank you.

Comment hidden (Intermittent Failures Robot)

Daniel Varga [:dvarga]

Comment 65

•

5 years ago

In the last 7 days there were 38 failures associated with this bug: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-09-13&endday=2019-09-20&tree=all&bug=1474041
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=267612548&repo=autoland&lineNumber=38828
Occurs on linux64, linux64-ccov, macosx1014-64, windows10-64, windows10-64-ccov, windows10-64-qr debug build types.

Comment hidden (Intermittent Failures Robot)

Rob Wu [:robwu]

Assignee

Comment 67

•

5 years ago

I have taken another look, and although I can still not reproduce locally, I can see a potential code path for the issue to occur:

browser.windows.create is called by the test - https://searchfox.org/mozilla-central/rev/e3fc8f8970491aef14d3212b2d052942f4d29818/toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js#112
The implementation of browser.windows.create waits for the window to be ready: https://searchfox.org/mozilla-central/rev/e3fc8f8970491aef14d3212b2d052942f4d29818/browser/components/extensions/parent/ext-windows.js#355-360
While waiting, the browser.windows.onCreated event may propagate down to the extension - https://searchfox.org/mozilla-central/rev/e3fc8f8970491aef14d3212b2d052942f4d29818/browser/components/extensions/parent/ext-windows.js#69
The test resumes and somehow completes very quickly, before the window is considered ready.
The extension closes the window, and the browser.windows.create call is still stuck, and the closure prevents the window object from being GC'd, which results in a memory leak.

I'm going to submit a patch that prevents this from happening. If the bug goes away, then I will file a follow-up bug to fix the leaky logic in the windows.create implementation.

Assignee: nobody → rob

Status: NEW → ASSIGNED

Rob Wu [:robwu]

Assignee

Comment 68

•

5 years ago

Attached file Bug 1474041 - Wait for browser.windows.create instead of onCreated (deleted) — Details

The browser.windows.onCreated event is triggered before
browser.windows.create returns. Waiting until browser.windows.create has
resolved may resolve the memory leak from bug 1474041.

Pulsebot

Comment 69

•

5 years ago

Pushed by rob@robwu.nl: https://hg.mozilla.org/integration/autoland/rev/5256af0d8646 Wait for browser.windows.create instead of onCreated r=rpl

Stefan Hindli [:stefan_hindli]

Comment 70

•

5 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/5256af0d8646

Status: ASSIGNED → RESOLVED

Closed: 5 years ago

status-firefox71: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla71

Ryan VanderMeulen [:RyanVM]

Updated

•

5 years ago

status-firefox69: --- → wontfix

status-firefox70: --- → affected

status-firefox-esr60: --- → unaffected

status-firefox-esr68: --- → affected

Comment hidden (Intermittent Failures Robot)

Rob Wu [:robwu]

Assignee

Updated

•

5 years ago

Depends on: 1584924

Ryan VanderMeulen [:RyanVM]

Comment 73

•

5 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-beta/rev/ae69a9019821

status-firefox70: affected → fixed

Flags: in-testsuite+

Ryan VanderMeulen [:RyanVM]

Comment 74

•

5 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-esr68/rev/6cd4301ea11c

status-firefox-esr68: affected → fixed

Andreea Pavel [:apavel]

Updated

•

5 years ago

Regressions: 1584391

Rob Wu [:robwu]

Assignee

Updated

•

5 years ago

Flags: needinfo?(rob)