1590933 - Intermittent Linux, Windows remote/test/browser/page/browser_captureScreenshot.js | Uncaught exception - at chrome://remote/content/Error.jsm:25 - RemoteAgentError

Status: RESOLVED DUPLICATE of bug 1594871

(Remote Protocol :: CDP, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=272667393&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/M-juUZmaSBe0f0BZcUOJ6A/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-10-23T23:14:44.428Z] 23:14:44 INFO - TEST-START | remote/test/browser/browser_page_captureScreenshot.js
[task 2019-10-23T23:14:44.438Z] 23:14:44 INFO - GECKO(2300) | DevTools listening on ws://localhost:9222/devtools/browser/b4da0197-b5f0-43ec-a2f5-fb798ae0d345
[task 2019-10-23T23:14:44.439Z] 23:14:44 INFO - GECKO(2300) | ++DOCSHELL 000002415654A000 == 10 [pid = 11236] [id = {4c25cdd7-1226-46be-8fb9-3c1aa50e34f9}]
[task 2019-10-23T23:14:44.439Z] 23:14:44 INFO - GECKO(2300) | ++DOMWINDOW == 23 (000002415F6422E0) [pid = 11236] [serial = 34] [outer = 0000000000000000]
[task 2019-10-23T23:14:44.439Z] 23:14:44 INFO - GECKO(2300) | ++DOMWINDOW == 24 (000002415543EC00) [pid = 11236] [serial = 35] [outer = 000002415F6422E0]
[task 2019-10-23T23:14:44.444Z] 23:14:44 INFO - GECKO(2300) | ++DOMWINDOW == 25 (0000024159386000) [pid = 11236] [serial = 36] [outer = 000002415F6422E0]
[task 2019-10-23T23:14:44.484Z] 23:14:44 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file z:/build/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2019-10-23T23:14:44.646Z] 23:14:44 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file z:/build/build/src/extensions/permissions/nsPermission.cpp, line 42
[task 2019-10-23T23:14:44.646Z] 23:14:44 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: '!principal', file z:/build/build/src/netwerk/cookie/CookieSettings.cpp, line 132
[task 2019-10-23T23:14:44.647Z] 23:14:44 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/toolkit/components/antitracking/StorageAccess.cpp, line 33
[task 2019-10-23T23:14:44.647Z] 23:14:44 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file z:/build/build/src/extensions/permissions/nsPermission.cpp, line 42
[task 2019-10-23T23:14:44.647Z] 23:14:44 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: '!principal', file z:/build/build/src/netwerk/cookie/CookieSettings.cpp, line 132
[task 2019-10-23T23:14:44.647Z] 23:14:44 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/toolkit/components/antitracking/StorageAccess.cpp, line 33
[task 2019-10-23T23:14:44.652Z] 23:14:44 INFO - GECKO(2300) | ++DOCSHELL 0000019A9D158000 == 2 [pid = 10840] [id = {33a0ab9d-7d34-4548-b5ec-2b0077b8b0e1}]
[task 2019-10-23T23:14:44.652Z] 23:14:44 INFO - GECKO(2300) | ++DOMWINDOW == 9 (0000019AA3F125C0) [pid = 10840] [serial = 11] [outer = 0000000000000000]
[task 2019-10-23T23:14:44.652Z] 23:14:44 INFO - GECKO(2300) | ++DOMWINDOW == 10 (0000019AA326A400) [pid = 10840] [serial = 12] [outer = 0000019AA3F125C0]
[task 2019-10-23T23:14:44.670Z] 23:14:44 INFO - GECKO(2300) | ++DOMWINDOW == 11 (0000019AA5944800) [pid = 10840] [serial = 13] [outer = 0000019AA3F125C0]
[task 2019-10-23T23:14:44.871Z] 23:14:44 INFO - GECKO(2300) | --DOCSHELL 0000024156546000 == 9 [pid = 11236] [id = {41c06607-3bfc-430f-98e3-6cfcd8be8a81}] [url = about:blank]
[task 2019-10-23T23:14:44.871Z] 23:14:44 INFO - GECKO(2300) | --DOCSHELL 0000024156540800 == 8 [pid = 11236] [id = {0b9e3935-d096-478c-93a9-157d40ffff0f}] [url = about:blank]
[task 2019-10-23T23:14:44.871Z] 23:14:44 INFO - GECKO(2300) | --DOCSHELL 000002415C15E000 == 7 [pid = 11236] [id = {6e5959e4-d31c-4535-8d50-57dc27fece2e}] [url = about:blank]
[task 2019-10-23T23:14:45.176Z] 23:14:45 INFO - GECKO(2300) | --DOMWINDOW == 2 (000001624E87CC00) [pid = 9396] [serial = 2] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:45.176Z] 23:14:45 INFO - GECKO(2300) | --DOCSHELL 0000016248755000 == 0 [pid = 9396] [id = {ae5ce71a-86c7-42ab-b533-b5fce824d625}] [url = about:blank]
[task 2019-10-23T23:14:45.215Z] 23:14:45 INFO - GECKO(2300) | --DOMWINDOW == 1 (000001624F51A020) [pid = 9396] [serial = 1] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:45.274Z] 23:14:45 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file z:/build/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2019-10-23T23:14:45.395Z] 23:14:45 INFO - GECKO(2300) | --DOMWINDOW == 9 (0000019DA992E400) [pid = 7660] [serial = 11] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:45.395Z] 23:14:45 INFO - GECKO(2300) | --DOCSHELL 0000019DA1255000 == 2 [pid = 7660] [id = {9543d66e-0cab-4b95-ab61-b5a49e3aee75}] [url = data:text/html;charset=utf-8,%3C!doctype%20html%3E%0A%3Cmeta%20charset%3Dutf-8%3E%0Afirst]
[task 2019-10-23T23:14:45.454Z] 23:14:45 INFO - GECKO(2300) | --DOMWINDOW == 8 (0000019DA9109980) [pid = 7660] [serial = 6] [outer = 0000000000000000] [url = data:text/html;charset=utf-8,%3C!doctype%20html%3E%0A%3Cmeta%20charset%3Dutf-8%3E%0Afirst]
[task 2019-10-23T23:14:45.648Z] 23:14:45 INFO - GECKO(2300) | --DOMWINDOW == 24 (000002415716F400) [pid = 11236] [serial = 25] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:45.648Z] 23:14:45 INFO - GECKO(2300) | --DOMWINDOW == 23 (0000024155440C00) [pid = 11236] [serial = 28] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:45.688Z] 23:14:45 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file z:/build/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2019-10-23T23:14:46.171Z] 23:14:46 INFO - GECKO(2300) | --DOCSHELL 0000029E3D454800 == 0 [pid = 11824] [id = {32e68742-c01b-4029-a373-6c231192e59e}] [url = about:blank]
[task 2019-10-23T23:14:46.372Z] 23:14:46 INFO - GECKO(2300) | --DOMWINDOW == 10 (0000019A9D1BCC00) [pid = 10840] [serial = 3] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:46.372Z] 23:14:46 INFO - GECKO(2300) | --DOMWINDOW == 9 (0000019AA3267C00) [pid = 10840] [serial = 6] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:46.372Z] 23:14:46 INFO - GECKO(2300) | --DOMWINDOW == 8 (0000019AA5936C00) [pid = 10840] [serial = 4] [outer = 0000000000000000] [url = data:text/html;charset=utf-8,%3C!doctype%20html%3E%0A%3Cmeta%20charset%3Dutf-8%3E%0A%3Cscript%3Econsole.log(%22foo%22)%3C%2Fscript%3E]
[task 2019-10-23T23:14:46.372Z] 23:14:46 INFO - GECKO(2300) | --DOCSHELL 0000019A9D154000 == 1 [pid = 10840] [id = {6d64b21b-2463-46f5-97bf-8202eb66067a}] [url = about:blank]
[task 2019-10-23T23:14:46.411Z] 23:14:46 INFO - GECKO(2300) | ++DOMWINDOW == 9 (0000019AA3F78C00) [pid = 10840] [serial = 14] [outer = 0000019AA3F125C0]
[task 2019-10-23T23:14:46.451Z] 23:14:46 INFO - GECKO(2300) | --DOMWINDOW == 8 (0000019AA3F123E0) [pid = 10840] [serial = 5] [outer = 0000000000000000] [url = data:text/html;charset=utf-8,%3C!doctype%20html%3E%0A%3Cmeta%20charset%3Dutf-8%3E%0Asecond]
[task 2019-10-23T23:14:46.490Z] 23:14:46 INFO - GECKO(2300) | 1571872486484 RemoteAgent WARN [Exception... "Data conversion failed because significant data would be lost" nsresult: "0x80460003 (NS_ERROR_LOSS_OF_SIGNIFICANT_DATA)" location: "<unknown>" data: no] No traceback available
[task 2019-10-23T23:14:46.492Z] 23:14:46 INFO - GECKO(2300) | 1571872486487 RemoteAgent ERROR RemoteAgentError:
[task 2019-10-23T23:14:46.492Z] 23:14:46 INFO - GECKO(2300) | RemoteAgentError@chrome://remote/content/Error.jsm:25:5
[task 2019-10-23T23:14:46.492Z] 23:14:46 INFO - GECKO(2300) | fromJSON@chrome://remote/content/Error.jsm:72:17
[task 2019-10-23T23:14:46.492Z] 23:14:46 INFO - GECKO(2300) | this.add_task/<@chrome://mochitests/content/browser/remote/test/browser/head.js:58:32
[task 2019-10-23T23:14:46.492Z] 23:14:46 INFO - GECKO(2300) | AsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1067:34
[task 2019-10-23T23:14:46.492Z] 23:14:46 INFO - GECKO(2300) | Tester_execTest@chrome://mochikit/content/browser-test.js:1102:11
[task 2019-10-23T23:14:46.493Z] 23:14:46 INFO - GECKO(2300) | nextTest/<@chrome://mochikit/content/browser-test.js:930:14
[task 2019-10-23T23:14:46.493Z] 23:14:46 INFO - GECKO(2300) | SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67
[task 2019-10-23T23:14:46.837Z] 23:14:46 INFO - GECKO(2300) | 1571872486836 RemoteAgent INFO Stopped listening
[task 2019-10-23T23:14:46.857Z] 23:14:46 INFO - TEST-INFO | started process screenshot
[task 2019-10-23T23:14:46.939Z] 23:14:46 INFO - TEST-INFO | screenshot: exit 0
[task 2019-10-23T23:14:46.940Z] 23:14:46 INFO - Buffered messages logged at 23:14:44
[task 2019-10-23T23:14:46.940Z] 23:14:46 INFO - Entering test bound
[task 2019-10-23T23:14:46.940Z] 23:14:46 INFO - Start the CDP server
[task 2019-10-23T23:14:46.940Z] 23:14:46 INFO - Buffered messages logged at 23:14:46
[task 2019-10-23T23:14:46.940Z] 23:14:46 INFO - CDP client instantiated
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - Check that captureScreenshot() captures the viewport by default
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - Stop the CDP server
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - Console message: [JavaScript Error: "(null)" {file: "chrome://remote/content/Error.jsm" line: 25}]
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - RemoteAgentError@chrome://remote/content/Error.jsm:25:5
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - fromJSON@chrome://remote/content/Error.jsm:72:17
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - this.add_task/<@chrome://mochitests/content/browser/remote/test/browser/head.js:58:32
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - AsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1067:34
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1102:11
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:930:14
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO -
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - Buffered messages finished
[task 2019-10-23T23:14:46.941Z] 23:14:46 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/browser_page_captureScreenshot.js | Uncaught exception - at chrome://remote/content/Error.jsm:25 - RemoteAgentError
[task 2019-10-23T23:14:46.942Z] 23:14:46 INFO - Leaving test bound
[task 2019-10-23T23:14:46.942Z] 23:14:46 INFO - Entering test bound
[task 2019-10-23T23:14:46.942Z] 23:14:46 INFO - Start the CDP server
[task 2019-10-23T23:14:46.942Z] 23:14:46 INFO - GECKO(2300) | DevTools listening on ws://localhost:9222/devtools/browser/b34a6240-b4a3-4f06-a77f-9666309f8f71
[task 2019-10-23T23:14:46.942Z] 23:14:46 INFO - GECKO(2300) | ++DOCSHELL 0000024156546800 == 8 [pid = 11236] [id = {faef6584-ede9-4114-bdcd-1087b6464803}]
[task 2019-10-23T23:14:46.942Z] 23:14:46 INFO - GECKO(2300) | ++DOMWINDOW == 24 (000002415FC76B60) [pid = 11236] [serial = 37] [outer = 0000000000000000]
[task 2019-10-23T23:14:46.942Z] 23:14:46 INFO - GECKO(2300) | ++DOMWINDOW == 25 (0000024157173C00) [pid = 11236] [serial = 38] [outer = 000002415FC76B60]
[task 2019-10-23T23:14:46.942Z] 23:14:46 INFO - GECKO(2300) | ++DOMWINDOW == 26 (000002415761A800) [pid = 11236] [serial = 39] [outer = 000002415FC76B60]
[task 2019-10-23T23:14:46.942Z] 23:14:46 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file z:/build/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2019-10-23T23:14:47.074Z] 23:14:47 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file z:/build/build/src/extensions/permissions/nsPermission.cpp, line 42
[task 2019-10-23T23:14:47.074Z] 23:14:47 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: '!principal', file z:/build/build/src/netwerk/cookie/CookieSettings.cpp, line 132
[task 2019-10-23T23:14:47.074Z] 23:14:47 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/toolkit/components/antitracking/StorageAccess.cpp, line 33
[task 2019-10-23T23:14:47.074Z] 23:14:47 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file z:/build/build/src/extensions/permissions/nsPermission.cpp, line 42
[task 2019-10-23T23:14:47.075Z] 23:14:47 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: '!principal', file z:/build/build/src/netwerk/cookie/CookieSettings.cpp, line 132
[task 2019-10-23T23:14:47.075Z] 23:14:47 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/toolkit/components/antitracking/StorageAccess.cpp, line 33
[task 2019-10-23T23:14:47.085Z] 23:14:47 INFO - GECKO(2300) | ++DOCSHELL 0000019A9D15A000 == 2 [pid = 10840] [id = {ba6cb45a-be1f-4e9d-9f44-3fed9e294238}]
[task 2019-10-23T23:14:47.085Z] 23:14:47 INFO - GECKO(2300) | ++DOMWINDOW == 9 (0000019AA3F127A0) [pid = 10840] [serial = 15] [outer = 0000000000000000]
[task 2019-10-23T23:14:47.085Z] 23:14:47 INFO - GECKO(2300) | ++DOMWINDOW == 10 (0000019AA3268C00) [pid = 10840] [serial = 16] [outer = 0000019AA3F127A0]
[task 2019-10-23T23:14:47.103Z] 23:14:47 INFO - GECKO(2300) | ++DOMWINDOW == 11 (0000019AA5944400) [pid = 10840] [serial = 17] [outer = 0000019AA3F127A0]
[task 2019-10-23T23:14:47.727Z] 23:14:47 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file z:/build/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2019-10-23T23:14:48.110Z] 23:14:48 INFO - GECKO(2300) | [Parent 11236, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file z:/build/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2019-10-23T23:14:48.638Z] 23:14:48 INFO - GECKO(2300) | --DOMWINDOW == 3 (000001AC8476B400) [pid = 844] [serial = 2] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:48.638Z] 23:14:48 INFO - GECKO(2300) | --DOCSHELL 000001ACFBC55000 == 0 [pid = 844] [id = {3966caac-6926-4665-a6ef-2c3e9134204c}] [url = http://example.com/browser/remote/test/browser/doc_network_requestWillBeSent.html]
[task 2019-10-23T23:14:48.677Z] 23:14:48 INFO - GECKO(2300) | --DOMWINDOW == 2 (000001AC86714020) [pid = 844] [serial = 1] [outer = 0000000000000000] [url = http://example.com/browser/remote/test/browser/doc_network_requestWillBeSent.html]
[task 2019-10-23T23:14:48.681Z] 23:14:48 INFO - GECKO(2300) | --DOCSHELL 0000023DFB854800 == 0 [pid = 4236] [id = {7695f2c1-dc2a-4a62-b1c6-672242768cb1}] [url = about:blank]
[task 2019-10-23T23:14:48.841Z] 23:14:48 INFO - CDP client instantiated
[task 2019-10-23T23:14:48.841Z] 23:14:48 INFO - Check that captureScreenshot() captures the viewport by default
[task 2019-10-23T23:14:48.841Z] 23:14:48 INFO - GECKO(2300) | ++DOMWINDOW == 12 (0000019AA59A6000) [pid = 10840] [serial = 18] [outer = 0000019AA3F127A0]
[task 2019-10-23T23:14:49.043Z] 23:14:49 INFO - TEST-PASS | remote/test/browser/browser_page_captureScreenshot.js | undefined assertion name -
[task 2019-10-23T23:14:49.043Z] 23:14:49 INFO - TEST-PASS | remote/test/browser/browser_page_captureScreenshot.js | undefined assertion name -
[task 2019-10-23T23:14:49.265Z] 23:14:49 INFO - GECKO(2300) | --DOMWINDOW == 0 (00000162487CA400) [pid = 9396] [serial = 3] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:49.425Z] 23:14:49 INFO - CDP client closed
[task 2019-10-23T23:14:49.427Z] 23:14:49 INFO - Stop the CDP server
[task 2019-10-23T23:14:49.427Z] 23:14:49 INFO - GECKO(2300) | 1571872489424 RemoteAgent INFO Stopped listening
[task 2019-10-23T23:14:49.427Z] 23:14:49 INFO - Leaving test bound
[task 2019-10-23T23:14:49.467Z] 23:14:49 INFO - GECKO(2300) | MEMORY STAT | vsize 2104236MB | vsizeMaxContiguous 65309354MB | residentFast 329MB | heapAllocated 134MB
[task 2019-10-23T23:14:49.467Z] 23:14:49 INFO - TEST-OK | remote/test/browser/browser_page_captureScreenshot.js | took 5032ms
[task 2019-10-23T23:14:49.468Z] 23:14:49 INFO - GECKO(2300) | ++DOCSHELL 0000019AA590C800 == 3 [pid = 10840] [id = {28ae4230-986a-499a-ad0e-1d5bd1185d58}]
[task 2019-10-23T23:14:49.468Z] 23:14:49 INFO - GECKO(2300) | ++DOMWINDOW == 13 (0000019AA3F12980) [pid = 10840] [serial = 19] [outer = 0000000000000000]
[task 2019-10-23T23:14:49.468Z] 23:14:49 INFO - GECKO(2300) | ++DOMWINDOW == 14 (0000019AA5944C00) [pid = 10840] [serial = 20] [outer = 0000019AA3F12980]
[task 2019-10-23T23:14:49.486Z] 23:14:49 INFO - GECKO(2300) | --DOMWINDOW == 7 (0000019DA917A400) [pid = 7660] [serial = 8] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:49.486Z] 23:14:49 INFO - GECKO(2300) | --DOCSHELL 0000019DA914E000 == 1 [pid = 7660] [id = {e8e555a2-662d-44f4-a7f6-f6b9d7915982}] [url = data:text/html;charset=utf-8,%3C!doctype%20html%3E%0A%3Cmeta%20charset%3Dutf-8%3E%0Afirst]
[task 2019-10-23T23:14:49.486Z] 23:14:49 INFO - GECKO(2300) | --DOMWINDOW == 6 (0000019DA717A800) [pid = 7660] [serial = 15] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:49.487Z] 23:14:49 INFO - GECKO(2300) | --DOMWINDOW == 5 (0000019DA99E1000) [pid = 7660] [serial = 12] [outer = 0000000000000000] [url = about:blank]
[task 2019-10-23T23:14:49.487Z] 23:14:49 INFO - GECKO(2300) | --DOMWINDOW == 4 (0000019DA992E000) [pid = 7660] [serial = 9] [outer = 0000000000000000] [url = data:text/html;charset=utf-8,%3C!doctype%20html%3E%0A%3Cmeta%20charset%3Dutf-8%3E%0Afirst]
[task 2019-10-23T23:14:49.492Z] 23:14:49 INFO - checking window state
[task 2019-10-23T23:14:49.517Z] 23:14:49 INFO - TEST-START | remote/test/browser/browser_page_frameNavigated.js

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Please note the following failure:

RemoteAgent WARN [Exception... "Data conversion failed because significant data would be lost" nsresult: "0x80460003 (NS_ERROR_LOSS_OF_SIGNIFICANT_DATA)" location: "<unknown>" data: no] No traceback available

This is a XPConnect failure message:
https://searchfox.org/mozilla-central/rev/2a355e56c490768be676689de18629485c9d699b/js/xpconnect/src/xpc.msg#127

It's use in mozilla-central is not that wide-spread:
https://searchfox.org/mozilla-central/search?q=NS_ERROR_LOSS_OF_SIGNIFICANT_DATA&path=

Given that this is a screenshot test I would assume that this might come from CrossProcessPaint.cpp. So some fragments of the captured data got lost? Sadly due to bug 1591161 it's not clear which line actually causes this problem.

This issue started yesterday, and I doubt that this is a regression from my patch on bug 1589625.

Matt, did something graphics-wise changed recently affecting the capture of screenshots?

Comment 2

[Intermittent Failures Robot]

21 failures in 4182 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 5
• autoland: 11
• try: 4
• mozilla-inbound: 1

Platform breakdown:

• windows7-32: 3
• windows10-64: 9
• windows7-32-shippable: 1
• linux64: 7
• windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590933&startday=2019-10-21&endday=2019-10-27&tree=all

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Note that this problem doesn't happen on MacOS but only Linux and Windows.

Comment 4

[Matt Woodrow (:mattwoodrow)]

I'm not aware of any recent changes that could affect this.

Do you have a changelog for the window where this started happening?

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

It somewhat started around the time when I landed my refactoring patch for the remote browser-chrome tests on bug 1589625. But not sure if that is really the problem here. Also due to bug 1591161 we loose the original stack of the failure, so that I cannot exactly tell where this problem happens exactly.

I will have a look at bug 1591161 so that we can have a proper stack for when it happens in CI.

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I was able to reproduce locally, and I can verify that this exception clearly comes from the call to drawSnapshot():
https://searchfox.org/mozilla-central/rev/11d9c7b7fa82fdfb8ac2a8f0864e9d8d5fe2b926/remote/domains/parent/Page.jsm#96-100

Matt, how can I enable the logging? Do I really have to compile Firefox myself after setting ENABLE_PAINT_LOG to 1? I wish their would be an environment variable for it.

Comment 7

[Matt Woodrow (:mattwoodrow)]

Unfortunately, yes.

Adding a MOZ_LOG option for this, instead of hardcoded options would be really good!

Comment 8

[Matt Woodrow (:mattwoodrow)]

Attachment: cross-process-paint-logging

You could apply this and build (hopefully I haven't made any typos), and then use MOZ_LOG=PaintFragment:5,CrossProcessPaint:5 in the env.

Comment 9

[Matt Woodrow (:mattwoodrow)]

Attachment: Bug 1590933 - Add MOZ_LOG support to CrossProcessPaint. r?jya

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7e150ae89101
Add MOZ_LOG support to CrossProcessPaint. r=jya

Comment 11

[Raul Gurzau (:RaulG)]

Backed out changeset 7e150ae89101 (bug 1590933) for build bustage at CrossProcessPaint.cpp on a CLOSED TREE.

Backout link: https://hg.mozilla.org/integration/autoland/rev/3e8d29ecc84d9ea58576d51e38a5daf87db2cd6c

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=273605925&resultStatus=testfailed%2Cbusted%2Cexception&revision=7e150ae891011e718dbc970bfef9a6404d35129f

Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=273605925&repo=autoland&lineNumber=23053

Log snippet:

[task 2019-10-30T03:05:46.692Z] 03:05:46 INFO - make[4]: Entering directory '/builds/worker/workspace/build/src/obj-firefox/dom/credentialmanagement'
[task 2019-10-30T03:05:46.692Z] 03:05:46 INFO - dom/credentialmanagement/Unified_cpp_credentialmanagement0.o
[task 2019-10-30T03:05:46.693Z] 03:05:46 INFO - make[4]: Leaving directory '/builds/worker/workspace/build/src/obj-firefox/dom/credentialmanagement'
[task 2019-10-30T03:05:46.970Z] 03:05:46 INFO - make[4]: Entering directory '/builds/worker/workspace/build/src/obj-firefox/gfx/ipc'
[task 2019-10-30T03:05:46.973Z] 03:05:46 INFO - /builds/worker/fetches/sccache/sccache /builds/worker/fetches/clang/bin/clang++ -o Unified_cpp_gfx_ipc0.o -c -I/builds/worker/workspace/build/src/obj-firefox/dist/stl_wrappers -I/builds/worker/workspace/build/src/obj-firefox/dist/system_wrappers -include /builds/worker/workspace/build/src/config/gcc_hidden.h -DNDEBUG=1 -DTRIMMED=1 -DOS_POSIX=1 -DOS_LINUX=1 -DSTATIC_EXPORTABLE_JS_API -DMOZ_HAS_MOZGLUE -DMOZILLA_INTERNAL_API -DIMPL_LIBXUL -I/builds/worker/workspace/build/src/gfx/ipc -I/builds/worker/workspace/build/src/obj-firefox/gfx/ipc -I/builds/worker/workspace/build/src/dom/ipc -I/builds/worker/workspace/build/src/toolkit/crashreporter -I/builds/worker/workspace/build/src/xpcom/threads -I/builds/worker/workspace/build/src/obj-firefox/ipc/ipdl/_ipdlheaders -I/builds/worker/workspace/build/src/ipc/chromium/src -I/builds/worker/workspace/build/src/ipc/glue -I/builds/worker/workspace/build/src/gfx/skia -I/builds/worker/workspace/build/src/gfx/skia/skia/include/config -I/builds/worker/workspace/build/src/gfx/skia/skia/include/core -I/builds/worker/workspace/build/src/gfx/skia/skia/include/docs -I/builds/worker/workspace/build/src/gfx/skia/skia/include/gpu -I/builds/worker/workspace/build/src/gfx/skia/skia/include/utils -I/builds/worker/workspace/build/src/obj-firefox/dist/include -I/builds/worker/workspace/build/src/obj-firefox/dist/include/nspr -I/builds/worker/workspace/build/src/obj-firefox/dist/include/nss -fPIC -DMOZILLA_CLIENT -include /builds/worker/workspace/build/src/obj-firefox/mozilla-config.h -Qunused-arguments -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=2 -fstack-protector-strong -Qunused-arguments -Wall -Wbitfield-enum-conversion -Wempty-body -Wignored-qualifiers -Woverloaded-virtual -Wpointer-arith -Wshadow-field-in-constructor-modified -Wsign-compare -Wtype-limits -Wunreachable-code -Wunreachable-code-return -Wwrite-strings -Wno-invalid-offsetof -Wclass-varargs -Wfloat-overflow-conversion -Wfloat-zero-conversion -Wloop-analysis -Wc++1z-compat -Wc++2a-compat -Wcomma -Wimplicit-fallthrough -Werror=non-literal-null-conversion -Wstring-conversion -Wtautological-overlap-compare -Wtautological-unsigned-enum-zero-compare -Wtautological-unsigned-zero-compare -Wno-error=tautological-type-limit-compare -Wno-inline-new-delete -Wno-error=deprecated-declarations -Wno-error=array-bounds -Wno-error=backend-plugin -Wno-error=return-std-move -Wno-error=atomic-alignment -Wformat -Wformat-security -Wno-gnu-zero-variadic-macro-arguments -Wno-unknown-warning-option -Wno-return-type-c-linkage -D_GLIBCXX_USE_CXX11_ABI=0 -fno-sized-deallocation -fno-aligned-new -fcrash-diagnostics-dir=/builds/worker/artifacts -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=2 -fstack-protector-strong -fno-exceptions -fno-strict-aliasing -fno-rtti -ffunction-sections -fdata-sections -fno-exceptions -fno-math-errno -pthread -pipe -g -Xclang -load -Xclang /builds/worker/workspace/build/src/obj-firefox/build/clang-plugin/libclang-plugin.so -Xclang -add-plugin -Xclang moz-check -O2 -fno-omit-frame-pointer -funwind-tables -Werror -I/builds/worker/workspace/build/src/obj-firefox/dist/include/cairo -I/builds/worker/workspace/build/src/widget/gtk/compat-gtk3 -pthread -I/usr/include/gtk-3.0 -I/usr/include/atk-1.0 -I/usr/include/at-spi2-atk/2.0 -I/usr/include/pango-1.0 -I/usr/include/gio-unix-2.0/ -I/usr/include/cairo -I/usr/include/gdk-pixbuf-2.0 -I/usr/include/glib-2.0 -I/usr/lib/x86_64-linux-gnu/glib-2.0/include -I/usr/include/harfbuzz -I/usr/include/freetype2 -I/usr/include/pixman-1 -I/usr/include/libpng12 -I/usr/include/gtk-3.0/unix-print -MD -MP -MF .deps/Unified_cpp_gfx_ipc0.o.pp Unified_cpp_gfx_ipc0.cpp
[task 2019-10-30T03:05:46.973Z] 03:05:46 INFO - In file included from Unified_cpp_gfx_ipc0.cpp:20:
[task 2019-10-30T03:05:46.973Z] 03:05:46 ERROR - /builds/worker/workspace/build/src/gfx/ipc/CrossProcessPaint.cpp:249:56: error: format specifies type 'unsigned long long' but the argument has type 'uint64_t' (aka 'unsigned long') [-Werror,-Wformat]
[task 2019-10-30T03:05:46.973Z] 03:05:46 INFO - CPP_LOG("Receiving fragment from %p(%llu).\n", aWGP, (uint64_t)surfaceId);
[task 2019-10-30T03:05:46.973Z] 03:05:46 INFO - ~~~~ ^~~~~~~~~~~~~~~~~~~
[task 2019-10-30T03:05:46.973Z] 03:05:46 INFO - %lu
[task 2019-10-30T03:05:46.973Z] 03:05:46 INFO - /builds/worker/workspace/build/src/gfx/ipc/CrossProcessPaint.cpp:32:59: note: expanded from macro 'CPP_LOG'
[task 2019-10-30T03:05:46.973Z] 03:05:46 INFO - MOZ_LOG(gCrossProcessPaintLog, LogLevel::Debug, (msg, ##VA_ARGS))
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - ~~~ ^~~~~~~~~~~
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/Logging.h:271:56: note: expanded from macro 'MOZ_LOG'
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - MOZ_LOG_EXPAND_ARGS _args);
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - ^~~~~
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/Logging.h:213:34: note: expanded from macro 'MOZ_LOG_EXPAND_ARGS'
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - #define MOZ_LOG_EXPAND_ARGS(...) VA_ARGS
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - ^~~~~~~~~~~
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - In file included from Unified_cpp_gfx_ipc0.cpp:20:
[task 2019-10-30T03:05:46.974Z] 03:05:46 ERROR - /builds/worker/workspace/build/src/gfx/ipc/CrossProcessPaint.cpp:267:15: error: format specifies type 'unsigned long long' but the argument has type 'uint64_t' (aka 'unsigned long') [-Werror,-Wformat]
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - (uint64_t)dependency);
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - ^~~~~~~~~~~~~~~~~~~~
[task 2019-10-30T03:05:46.974Z] 03:05:46 INFO - /builds/worker/workspace/build/src/gfx/ipc/CrossProcessPaint.cpp:32:59: note: expanded from macro 'CPP_LOG'
[task 2019-10-30T03:05:46.975Z] 03:05:46 INFO - MOZ_LOG(gCrossProcessPaintLog, LogLevel::Debug, (msg, ##VA_ARGS))
[task 2019-10-30T03:05:46.976Z] 03:05:46 INFO - ~~~ ^~~~~~~~~~~
[task 2019-10-30T03:05:46.976Z] 03:05:46 INFO - /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/Logging.h:271:56: note: expanded from macro 'MOZ_LOG'
[task 2019-10-30T03:05:46.976Z] 03:05:46 INFO - MOZ_LOG_EXPAND_ARGS _args);
[task 2019-10-30T03:05:46.976Z] 03:05:46 INFO - ^~~~~
[task 2019-10-30T03:05:46.976Z] 03:05:46 INFO - /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/Logging.h:213:34: note: expanded from macro 'MOZ_LOG_EXPAND_ARGS'
[task 2019-10-30T03:05:46.976Z] 03:05:46 INFO - #define MOZ_LOG_EXPAND_ARGS(...) VA_ARGS
[task 2019-10-30T03:05:46.976Z] 03:05:46 INFO - ^~~~~~~~~~~
[task 2019-10-30T03:05:46.976Z] 03:05:46 INFO - In file included from Unified_cpp_gfx_ipc0.cpp:20:
[task 2019-10-30T03:05:46.976Z] 03:05:46 ERROR - /builds/worker/workspace/build/src/gfx/ipc/CrossProcessPaint.cpp:360:41: error: format specifies type 'unsigned long long' but the argument has type 'uint64_t' (aka 'unsigned long') [-Werror,-Wformat]
[task 2019-10-30T03:05:46.976Z] 03:05:46 INFO - CPP_LOG("Resolving fragment %llu.\n", (uint64_t)aTabId);

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Matt, mind moving the patch for logging to a separate bug so that we can keep this bug for fixing the real underlying problem? I think I will have to wait a bit until the log patch landed.

Comment 13

[Phabricator Automation]

Comment on attachment 9105114 [details]
Bug 1590933 - Add MOZ_LOG support to CrossProcessPaint. r?jya

Revision D51036 was moved to bug 1592849. Setting attachment 9105114 [details] to obsolete.

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Location of the file has been changed. Updating the summary to reflect that and to not cause more duplicates.

I will have a look in creating a log today.

Comment 16

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So here the log output for the last successful screenshot, and the one failing:

2019-11-01 13:41:31.099471 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Starting paint. [wgp=0x7f2d77d1a400, scale=1,000000, color=(255, 255, 255, 255)]
2019-11-01 13:41:31.099513 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Queueing paint for 0x7f2d77d1a400.
2019-11-01 13:41:31.121858 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Receiving fragment from 0x7f2d77d1a400(80).
2019-11-01 13:41:31.121887 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Starting to resolve fragments.
2019-11-01 13:41:31.121893 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Resolving fragment 80.
2019-11-01 13:41:31.125005 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Resolved all fragments.
2019-11-01 13:41:31.125051 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Success, fulfilling promise.
2019-11-01 13:41:35.092198 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Starting paint. [wgp=0x7f2d77d1a340, scale=1,000000, color=(255, 255, 255, 255)]
2019-11-01 13:41:35.092235 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Queueing paint for 0x7f2d77d1a340.

As it looks like we do not receive a fragment and as such return early:

https://searchfox.org/mozilla-central/rev/ce02064d8afc8673cef83c92896ee873bd35e7ae/gfx/ipc/CrossProcessPaint.cpp#365

Not sure what to do to figure out why no fragment is actually send. The specific fragment id doesn't appear in any of the content log files.

Comment 17

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 6
• try: 2

Platform breakdown:

• linux64: 2
• windows10-64: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590933&startday=2019-10-28&endday=2019-11-03&tree=all

Comment 18

[Intermittent Failures Robot]

26 failures in 963 pushes (0.027 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 3
• try: 2
• autoland: 21

Platform breakdown:

• windows10-64: 8
• linux64: 1
• windows10-64-shippable: 6
• windows7-32-shippable: 7
• linux64-shippable: 2
• windows10-64-ccov: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590933&startday=2019-11-07&endday=2019-11-07&tree=all

Comment 19

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

This is almost permafailing on Windows shippable now: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=windows%2Cship%2Cremote&fromchange=ba60dd480690fa93615a42b67932676f89459614&tochange=829d65c3ea2a78cb4c71fa272bfdc7393330e3bc&selectedJob=275206074

Another issue arising from the landing of bug 1593560 etc. and bug 1587846?

Comment 20

[Henrik Skupin [:whimboo][⌚️UTC+2]]

See also bug 1594871 for a different failure and which we had to skip for now. Maybe investigating that will also help here. Adding as see also reference for now.

Comment 21

[Henrik Skupin [:whimboo][⌚️UTC+2]]

All the screenshot tests are racy because of a missing await keyword. See bug 1594871 comment 8.

Maybe the patch on that other bug will also fix that one. I will mark it as dependent now.

Comment 22

[Intermittent Failures Robot]

54 failures in 895 pushes (0.06 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 40
• mozilla-central: 12
• try: 2

Platform breakdown:

• windows10-64: 14
• windows7-32-shippable: 11
• windows10-64-shippable: 22
• windows7-32: 4
• macosx1014-64-shippable: 1
• linux64-shippable: 1
• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590933&startday=2019-11-08&endday=2019-11-08&tree=all

Comment 23

[Matt Woodrow (:mattwoodrow)]

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #16)

So here the log output for the last successful screenshot, and the one failing:

2019-11-01 13:41:31.099471 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Starting paint. [wgp=0x7f2d77d1a400, scale=1,000000, color=(255, 255, 255, 255)]
2019-11-01 13:41:31.099513 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Queueing paint for 0x7f2d77d1a400.
2019-11-01 13:41:31.121858 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Receiving fragment from 0x7f2d77d1a400(80).
2019-11-01 13:41:31.121887 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Starting to resolve fragments.
2019-11-01 13:41:31.121893 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Resolving fragment 80.
2019-11-01 13:41:31.125005 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Resolved all fragments.
2019-11-01 13:41:31.125051 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Success, fulfilling promise.
2019-11-01 13:41:35.092198 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Starting paint. [wgp=0x7f2d77d1a340, scale=1,000000, color=(255, 255, 255, 255)]
2019-11-01 13:41:35.092235 UTC - [Parent 29482: Main Thread]: D/CrossProcessPaint Queueing paint for 0x7f2d77d1a340.

As it looks like we do not receive a fragment and as such return early:

https://searchfox.org/mozilla-central/rev/ce02064d8afc8673cef83c92896ee873bd35e7ae/gfx/ipc/CrossProcessPaint.cpp#365

Not sure what to do to figure out why no fragment is actually send. The specific fragment id doesn't appear in any of the content log files.

Sorry for taking a while to look at this.

I think it indeed the same as bug 1594871.

It looks like the only path that could fail without us logging anything is when WindowGlobalParent::DrawSnapshotInternal calls LostFragment.

I think we're requesting the snapshot too early, so the current document is still the previous one (about:blank?). We're sending a message to request a snapshot from that WindowGlobal, but then it gets torn down as we load the actual document, so the snapshot gets rejected.

Comment 24

[Intermittent Failures Robot]

94 failures in 4850 pushes (0.019 failures/push) were associated with this bug in the last 7 days.

This is the #14 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 70
• mozilla-central: 18
• try: 6

Platform breakdown:

• windows10-64: 30
• windows10-64-ccov: 5
• linux64-ccov: 1
• windows7-32-shippable: 20
• linux64: 2
• windows10-64-shippable: 28
• linux64-shippable: 3
• windows7-32: 4
• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1590933&startday=2019-11-04&endday=2019-11-10&tree=all

Comment 25

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Yes, we can close it as duplicate of bug 1594871. Good that the other test triggered it permanently across all platforms, so I was able to more easily investigate it.