1676644 - Intermittent toolkit/components/printing/tests/browser_preview_switch_print_selected.js | Found a tab after previous test timed out: about:printpreview -

Status: RESOLVED INCOMPLETE

(Toolkit :: Printing, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-11-11T12:52:13.191Z] 12:52:13     INFO - TEST-START | toolkit/components/printing/tests/browser_preview_switch_print_selected.js
[task 2020-11-11T12:52:13.287Z] 12:52:13     INFO - GECKO(7669) | [Child 8524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fc6dc3f0000 == 1 [pid = 8524] [id = 0]
[task 2020-11-11T12:52:13.315Z] 12:52:13     INFO - GECKO(7669) | Waiting for browser load
[task 2020-11-11T12:52:13.316Z] 12:52:13     INFO - GECKO(7669) | Waiting for browser state change
[task 2020-11-11T12:52:13.324Z] 12:52:13     INFO - GECKO(7669) | [Child 8524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7fc6d61d0040) [pid = 8524] [serial = 1] [outer = (nil)]
[task 2020-11-11T12:52:13.324Z] 12:52:13     INFO - GECKO(7669) | [Child 8524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7fc6d6149800) [pid = 8524] [serial = 2] [outer = 0x7fc6d61d0040]
[task 2020-11-11T12:52:13.327Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f45ca4f0000 == 3 [pid = 8466] [id = 0] [url = http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html]
[task 2020-11-11T12:52:13.329Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f45c4258c00 == 2 [pid = 8466] [id = 1] [url = about:printpreview]
[task 2020-11-11T12:52:13.329Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f45c33a2400 == 1 [pid = 8466] [id = 3] [url = about:printpreview]
[task 2020-11-11T12:52:13.329Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f45ca4f6400 == 0 [pid = 8466] [id = 2] [url = about:printpreview]
[task 2020-11-11T12:52:13.491Z] 12:52:13     INFO - GECKO(7669) | Saw state f0001 and status 0
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (0x7f45c33a3800) [pid = 8466] [serial = 12] [outer = (nil)] [url = about:blank]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (0x7f45c42a7000) [pid = 8466] [serial = 6] [outer = (nil)] [url = about:printpreview]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (0x7f45c33a0400) [pid = 8466] [serial = 10] [outer = (nil)] [url = about:printpreview]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (0x7f45c424f000) [pid = 8466] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (0x7f45ca4fd800) [pid = 8466] [serial = 9] [outer = (nil)] [url = about:blank]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (0x7f45c33a6800) [pid = 8466] [serial = 13] [outer = (nil)] [url = about:printpreview]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (0x7f45c2370000) [pid = 8466] [serial = 14] [outer = (nil)] [url = about:printpreview]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (0x7f45c42cf040) [pid = 8466] [serial = 1] [outer = (nil)] [url = http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (0x7f45c42cf3c0) [pid = 8466] [serial = 4] [outer = (nil)] [url = http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (0x7f45c42cfe40) [pid = 8466] [serial = 11] [outer = (nil)] [url = about:printpreview]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x7f45c42cfac0) [pid = 8466] [serial = 8] [outer = (nil)] [url = about:printpreview]
[task 2020-11-11T12:52:13.517Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7f45c4259c00) [pid = 8466] [serial = 5] [outer = (nil)] [url = about:blank]
[task 2020-11-11T12:52:13.520Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f45c42a7800) [pid = 8466] [serial = 7] [outer = (nil)] [url = http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html]
[task 2020-11-11T12:52:13.521Z] 12:52:13     INFO - GECKO(7669) | [Child 8466: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f45c4542400) [pid = 8466] [serial = 3] [outer = (nil)] [url = http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html]
[task 2020-11-11T12:52:13.542Z] 12:52:13     INFO - GECKO(7669) | [Child 8524, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2020-11-11T12:52:13.542Z] 12:52:13     INFO - GECKO(7669) | [Child 8524, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2020-11-11T12:52:13.551Z] 12:52:13     INFO - GECKO(7669) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpBKEtUr.mozrunner/runtests_leaks_tab_pid8614.log
[task 2020-11-11T12:52:13.554Z] 12:52:13     INFO - GECKO(7669) | [8614, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:251
[task 2020-11-11T12:52:13.575Z] 12:52:13     INFO - GECKO(7669) | [Child 8466, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3359
[task 2020-11-11T12:52:13.576Z] 12:52:13     INFO - GECKO(7669) | [Child 8524: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7fc6d6443400) [pid = 8524] [serial = 3] [outer = 0x7fc6d61d0040]
[task 2020-11-11T12:52:13.597Z] 12:52:13     INFO - GECKO(7669) | [Child 8466, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4287
[task 2020-11-11T12:52:13.725Z] 12:52:13     INFO - GECKO(7669) | [Child 8614, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:628
[task 2020-11-11T12:52:13.803Z] 12:52:13     INFO - GECKO(7669) | Saw state c0010 and status 0

[task 2020-11-11T12:53:43.227Z] 12:53:43     INFO - TEST-INFO | started process screentopng
[task 2020-11-11T12:53:43.401Z] 12:53:43     INFO - TEST-INFO | screentopng: exit 0
[task 2020-11-11T12:53:43.401Z] 12:53:43     INFO - Buffered messages logged at 12:52:13
[task 2020-11-11T12:53:43.401Z] 12:53:43     INFO - Entering test bound set_simplify_and_reader_pref
[task 2020-11-11T12:53:43.402Z] 12:53:43     INFO - Leaving test bound set_simplify_and_reader_pref
[task 2020-11-11T12:53:43.403Z] 12:53:43     INFO - Entering test bound switch_print_preview_browsers
[task 2020-11-11T12:53:43.403Z] 12:53:43     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.com/browser/toolkit/components/printing/tests/simplifyArticleSample.html" line: 0}]
[task 2020-11-11T12:53:43.404Z] 12:53:43     INFO - Buffered messages logged at 12:52:14
[task 2020-11-11T12:53:43.404Z] 12:53:43     INFO - TEST-PASS | toolkit/components/printing/tests/browser_preview_switch_print_selected.js | Should have initial content. - "Article title" == "Article title" - 
[task 2020-11-11T12:53:43.405Z] 12:53:43     INFO - Buffered messages logged at 12:52:15
[task 2020-11-11T12:53:43.406Z] 12:53:43     INFO - Console message: [JavaScript Error: "TypeError: can't access property "windowGlobalChild", thisWindow is null" {file: "resource://gre/actors/PrintingChild.jsm" line: 174}]
[task 2020-11-11T12:53:43.406Z] 12:53:43     INFO - Buffered messages finished
[task 2020-11-11T12:53:43.407Z] 12:53:43     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/printing/tests/browser_preview_switch_print_selected.js | Test timed out - 
[task 2020-11-11T12:53:43.407Z] 12:53:43     INFO - GECKO(7669) | MEMORY STAT | vsize 3165MB | residentFast 362MB | heapAllocated 98MB
[task 2020-11-11T12:53:43.407Z] 12:53:43     INFO - TEST-OK | toolkit/components/printing/tests/browser_preview_switch_print_selected.js | took 90067ms
[task 2020-11-11T12:53:43.408Z] 12:53:43     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-11T12:53:43.408Z] 12:53:43     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/printing/tests/browser_preview_switch_print_selected.js | Found a tab after previous test timed out: about:printpreview - 
[task 2020-11-11T12:53:43.409Z] 12:53:43     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-11T12:53:43.409Z] 12:53:43     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/printing/tests/browser_preview_switch_print_selected.js | Found a tab after previous test timed out: about:printpreview - 
[task 2020-11-11T12:53:43.409Z] 12:53:43     INFO - GECKO(7669) | JavaScript error: chrome://browser/content/tabbrowser-tabs.js, line 1097: TypeError: can't access property "closing", selectedTab is null
[task 2020-11-11T12:53:43.410Z] 12:53:43     INFO - Console message: [JavaScript Error: "TypeError: can't access property "closing", selectedTab is null" {file: "chrome://browser/content/tabbrowser-tabs.js" line: 1097}]
[task 2020-11-11T12:53:51.341Z] 12:53:51     INFO - GECKO(7669) | [Child 8524: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc6d501ac00 == 3 [pid = 8524] [id = 3] [url = about:printpreview]
[task 2020-11-11T12:53:55.440Z] 12:53:55     INFO - GECKO(7669) | [Child 8524: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (0x7fc6f2764ac0) [pid = 8524] [serial = 11] [outer = (nil)] [url = about:printpreview]
[task 2020-11-11T12:53:59.498Z] 12:53:59     INFO - GECKO(7669) | [Child 8524: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (0x7fc6d501e800) [pid = 8524] [serial = 13] [outer = (nil)] [url = about:printpreview]
[task 2020-11-11T12:57:53.891Z] 12:57:53     INFO - Console message: [JavaScript Error: "Unknown Collection "main/nimbus-desktop-experiments"" {file: "resource://services-settings/RemoteSettingsClient.jsm" line: 160}]
[task 2020-11-11T12:57:53.891Z] 12:57:53     INFO - UnknownCollectionError@resource://services-settings/RemoteSettingsClient.jsm:160:5
[task 2020-11-11T12:57:53.891Z] 12:57:53     INFO - sync@resource://services-settings/RemoteSettingsClient.jsm:470:13
[task 2020-11-11T12:57:53.891Z] 12:57:53     INFO - 
[task 2020-11-11T13:01:27.505Z] 13:01:27     INFO - GECKO(7669) | [Parent 7669, Main Thread] WARNING: 'NS_FAILED(aRv)', file /builds/worker/checkouts/gecko/netwerk/ipc/NeckoParent.cpp:914
[task 2020-11-11T13:01:27.526Z] 13:01:27     INFO - GECKO(7669) | [Child 7891, Main Thread] WARNING: NS_ENSURE_TRUE(mRequest) failed: file /builds/worker/checkouts/gecko/netwerk/base/nsBaseChannel.cpp:928
[task 2020-11-11T13:01:53.869Z] 13:01:53     INFO - GECKO(7669) | 1605099713863	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates
[task 2020-11-11T13:01:53.873Z] 13:01:53     INFO - Console message: [JavaScript Error: "1605099713863	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2020-11-11T13:01:53.873Z] 13:01:53     INFO - append@resource://gre/modules/Log.jsm:723:12
[task 2020-11-11T13:01:53.873Z] 13:01:53     INFO - log@resource://gre/modules/Log.jsm:379:16
[task 2020-11-11T13:01:53.874Z] 13:01:53     INFO - error@resource://gre/modules/Log.jsm:387:10
[task 2020-11-11T13:01:53.874Z] 13:01:53     INFO - updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4015:25
[task 2020-11-11T13:01:53.874Z] 13:01:53     INFO - 
[task 2020-11-11T13:08:03.883Z] 13:08:03     INFO - Buffered messages finished
[task 2020-11-11T13:08:03.883Z] 13:08:03    ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/components/printing/tests/browser_preview_switch_print_selected.js (finished) | application timed out after 370 seconds with no output
[task 2020-11-11T13:08:03.884Z] 13:08:03    ERROR - Force-terminating active process(es).
[task 2020-11-11T13:08:03.884Z] 13:08:03     INFO - Determining child pids from psutil...
[task 2020-11-11T13:08:03.905Z] 13:08:03     INFO - [8200, 8234, 8263, 8318, 8347, 8348, 8402, 8432, 8466, 8467, 8524, 8557, 8614, 8300, 8464, 7815, 7835, 7891, 7917, 7923, 7962, 8586, 8020, 8028, 8031, 8173, 8100, 8132, 8134]
[task 2020-11-11T13:08:03.905Z] 13:08:03     INFO - ==> process 7669 launched child process 7693
[task 2020-11-11T13:08:03.905Z] 13:08:03     INFO - ==> process 7669 launched child process 7815
[task 2020-11-11T13:08:03.906Z] 13:08:03     INFO - ==> process 7669 launched child process 7835
[task 2020-11-11T13:08:03.906Z] 13:08:03     INFO - ==> process 7669 launched child process 7891
[task 2020-11-11T13:08:03.906Z] 13:08:03     INFO - ==> process 7669 launched child process 7917
[task 2020-11-11T13:08:03.907Z] 13:08:03     INFO - ==> process 7669 launched child process 7923
[task 2020-11-11T13:08:03.907Z] 13:08:03     INFO - ==> process 7669 launched child process 7962
[task 2020-11-11T13:08:03.907Z] 13:08:03     INFO - ==> process 7669 launched child process 8020
[task 2020-11-11T13:08:03.908Z] 13:08:03     INFO - ==> process 7669 launched child process 8028
[task 2020-11-11T13:08:03.908Z] 13:08:03     INFO - ==> process 7669 launched child process 8031
[task 2020-11-11T13:08:03.908Z] 13:08:03     INFO - ==> process 7669 launched child process 8100
[task 2020-11-11T13:08:03.909Z] 13:08:03     INFO - ==> process 7669 launched child process 8132
[task 2020-11-11T13:08:03.909Z] 13:08:03     INFO - ==> process 7669 launched child process 8134
[task 2020-11-11T13:08:03.909Z] 13:08:03     INFO - ==> process 7669 launched child process 8173
[task 2020-11-11T13:08:03.910Z] 13:08:03     INFO - ==> process 7669 launched child process 8200
[task 2020-11-11T13:08:03.910Z] 13:08:03     INFO - ==> process 7669 launched child process 8234
[task 2020-11-11T13:08:03.910Z] 13:08:03     INFO - ==> process 7669 launched child process 8263
[task 2020-11-11T13:08:03.911Z] 13:08:03     INFO - ==> process 7669 launched child process 8300
[task 2020-11-11T13:08:03.911Z] 13:08:03     INFO - ==> process 7669 launched child process 8318
[task 2020-11-11T13:08:03.911Z] 13:08:03     INFO - ==> process 7669 launched child process 8347
[task 2020-11-11T13:08:03.912Z] 13:08:03     INFO - ==> process 7669 launched child process 8348
[task 2020-11-11T13:08:03.912Z] 13:08:03     INFO - ==> process 7669 launched child process 8402
[task 2020-11-11T13:08:03.912Z] 13:08:03     INFO - ==> process 7669 launched child process 8432
[task 2020-11-11T13:08:03.912Z] 13:08:03     INFO - ==> process 7669 launched child process 8464
[task 2020-11-11T13:08:03.913Z] 13:08:03     INFO - ==> process 7669 launched child process 8466
[task 2020-11-11T13:08:03.913Z] 13:08:03     INFO - ==> process 7669 launched child process 8467
[task 2020-11-11T13:08:03.913Z] 13:08:03     INFO - ==> process 7669 launched child process 8524
[task 2020-11-11T13:08:03.914Z] 13:08:03     INFO - ==> process 7669 launched child process 8557
[task 2020-11-11T13:08:03.914Z] 13:08:03     INFO - ==> process 7669 launched child process 8586
[task 2020-11-11T13:08:03.914Z] 13:08:03     INFO - ==> process 7669 launched child process 8614
[task 2020-11-11T13:08:03.915Z] 13:08:03     INFO - Found child pids: set([7815, 8200, 8586, 7693, 7917, 8464, 8466, 8467, 7962, 7835, 8348, 8347, 8100, 8614, 8234, 8132, 8134, 8263, 8173, 8524, 8402, 7891, 8020, 8028, 8031, 8300, 8557, 8432, 7923, 8318])
[task 2020-11-11T13:08:03.916Z] 13:08:03     INFO - Failed to get child procs
[task 2020-11-11T13:08:03.916Z] 13:08:03     INFO - Killing process: 7815```

Comment 1

[Intermittent Failures Robot]

1 failures in 4040 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1676644&startday=2020-11-09&endday=2020-11-15&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 3712 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1676644&startday=2020-11-30&endday=2020-12-06&tree=all

Comment 3

[Intermittent Failures Robot]

2 failures in 4060 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-release: 1

Platform breakdown:

• linux1804-64-asan: 1
• linux1804-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1676644&startday=2020-12-07&endday=2020-12-13&tree=all

Comment 4

[Intermittent Failures Robot]

8 failures in 3421 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1
• autoland: 7

Platform breakdown:

• linux1804-64-devedition: 1
• linux1804-64: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1676644&startday=2020-12-14&endday=2020-12-20&tree=all

Comment 5

[Intermittent Failures Robot]

2 failures in 1450 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1
• autoland: 1

Platform breakdown:

• linux1804-64-devedition: 1
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1676644&startday=2020-12-21&endday=2020-12-27&tree=all

Comment 6

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.