Closed Bug 1474041 Opened 6 years ago Closed 5 years ago

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

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(firefox-esr60 unaffected, firefox-esr68 fixed, firefox69 wontfix, firefox70 fixed, firefox71 fixed)

RESOLVED FIXED
mozilla71
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- fixed
firefox69 --- wontfix
firefox70 --- fixed
firefox71 --- fixed

People

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

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [TV-bf pass:fail][stockwell needwork:owner])

Attachments

(1 file)

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]
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]
: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)
How can that even be related? That changed nothing for linux debug builds.
Flags: needinfo?(mh+mozilla) → needinfo?(jmaher)
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)
This test got added at the end of last week in bug 1347204.
Blocks: 1347204
No longer blocks: 1469088
Flags: needinfo?(jmathies)
Whiteboard: [TV-bf pass:fail] → [TV-bf pass:fail][stockwell needwork:owner]

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)

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)

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)

Okay Rob, thank you.

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.

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:

  1. 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
  2. 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
  3. 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
  4. The test resumes and somehow completes very quickly, before the window is considered ready.
  5. 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

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.

Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/5256af0d8646
Wait for browser.windows.create instead of onCreated r=rpl
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla71
Depends on: 1584924
Regressions: 1584391
Flags: needinfo?(rob)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: