1691034 - Intermittent layout/generic/crashtests/370174-3.html | load failed: timed out waiting for pending paint count to reach zero (waiting for updateCanvasPending)

Status: RESOLVED FIXED

(Core :: Layout, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=328983268&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZDRbZJosTme6hBiH7CKMhg/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZDRbZJosTme6hBiH7CKMhg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2021-02-05T13:17:09.660Z] 13:17:09     INFO - REFTEST TEST-START | layout/generic/crashtests/370174-3.html
[task 2021-02-05T13:17:09.660Z] 13:17:09     INFO - REFTEST TEST-LOAD | file:///Z:/task_1612529770/build/tests/reftest/tests/layout/generic/crashtests/370174-3.html | 2163 / 3887 (55%)
[task 2021-02-05T13:17:09.755Z] 13:17:09     INFO - [Parent 3800, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/startupcache/StartupCacheUtils.cpp:153
[task 2021-02-05T13:17:09.755Z] 13:17:09     INFO - JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-02-05T13:17:09.770Z] 13:17:09     INFO - [Parent 3800, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/startupcache/StartupCacheUtils.cpp:153
[task 2021-02-05T13:17:09.770Z] 13:17:09     INFO - JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-02-05T13:17:09.773Z] 13:17:09     INFO - [Parent 3800, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/startupcache/StartupCacheUtils.cpp:153
[task 2021-02-05T13:17:09.773Z] 13:17:09     INFO - JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-02-05T13:17:09.776Z] 13:17:09     INFO - [Parent 3800, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/startupcache/StartupCacheUtils.cpp:153
[task 2021-02-05T13:17:09.776Z] 13:17:09     INFO - JavaScript error: resource://specialpowers/AppTestDelegateParent.jsm, line 10: NS_ERROR_NOT_AVAILABLE:
[task 2021-02-05T13:17:10.512Z] 13:17:10     INFO - [Child 4344, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
...
...
...
[task 2021-02-05T13:20:03.402Z] 13:20:03     INFO - [Child 4344, Main Thread] WARNING: Error sending reply: file /builds/worker/workspace/obj-build/ipc/ipdl/PDocumentChannelChild.cpp:288
[task 2021-02-05T13:20:11.547Z] 13:20:11     INFO - [Parent 3800, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A (NS_ERROR_MALFORMED_URI): file /builds/worker/checkouts/gecko/caps/BasePrincipal.cpp:1149
[task 2021-02-05T13:20:11.551Z] 13:20:11     INFO - JavaScript error: resource://gre/modules/PurgeTrackerService.jsm, line 387: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIScriptSecurityManager.createContentPrincipalFromOrigin]
[task 2021-02-05T13:20:16.409Z] 13:20:16     INFO - [Child 4344, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
[task 2021-02-05T13:20:16.409Z] 13:20:16     INFO - [Child 4344, Main Thread] WARNING: Error sending reply: file /builds/worker/workspace/obj-build/ipc/ipdl/PDocumentChannelChild.cpp:288
[task 2021-02-05T13:20:16.414Z] 13:20:16     INFO - [Parent 3800, Main Thread] WARNING: Suboptimal indexes for the SQL statement 0x1a3062f0 (http://mzl.la/1FuID0j).: file /builds/worker/checkouts/gecko/storage/mozStoragePrivateHelpers.cpp:113
[task 2021-02-05T13:20:16.854Z] 13:20:16     INFO - [Child 4344, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
...
...
...
[task 2021-02-05T13:22:10.525Z] 13:22:10     INFO - [Child 4344, Main Thread] WARNING: Error sending reply: file /builds/worker/workspace/obj-build/ipc/ipdl/PDocumentChannelChild.cpp:288
[task 2021-02-05T13:22:11.176Z] 13:22:11     INFO - REFTEST TEST-UNEXPECTED-FAIL | layout/generic/crashtests/370174-3.html | load failed: timed out waiting for pending paint count to reach zero (waiting for updateCanvasPending)
[task 2021-02-05T13:22:11.176Z] 13:22:11     INFO - REFTEST INFO | Saved log: START file:///Z:/task_1612529770/build/tests/reftest/tests/layout/generic/crashtests/370174-3.html
[task 2021-02-05T13:22:11.177Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2021-02-05T13:22:11.178Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2021-02-05T13:22:11.178Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2021-02-05T13:22:11.179Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2021-02-05T13:22:11.180Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2021-02-05T13:22:11.180Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2021-02-05T13:22:11.181Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2021-02-05T13:22:11.181Z] 13:22:11     INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2021-02-05T13:22:11.181Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd
[task 2021-02-05T13:22:11.182Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2021-02-05T13:22:11.182Z] 13:22:11     INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2021-02-05T13:22:11.183Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress
[task 2021-02-05T13:22:11.184Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in file:///Z:/task_1612529770/build/tests/reftest/tests/layout/generic/crashtests/370174-3.html
[task 2021-02-05T13:22:11.184Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] AfterPaintListener in about:blank
[task 2021-02-05T13:22:11.185Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] FromChildAfterPaintListener from about:blank
[task 2021-02-05T13:22:11.185Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] FromChildAfterPaintListener from about:blank
[task 2021-02-05T13:22:11.186Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] FromChildAfterPaintListener from about:blank
[task 2021-02-05T13:22:11.187Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] FromChildAfterPaintListener from about:blank
[task 2021-02-05T13:22:11.187Z] 13:22:11     INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2021-02-05T13:22:11.188Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd
[task 2021-02-05T13:22:11.189Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2021-02-05T13:22:11.189Z] 13:22:11     INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2021-02-05T13:22:11.190Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress
[task 2021-02-05T13:22:11.191Z] 13:22:11     INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2021-02-05T13:22:11.191Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd
[task 2021-02-05T13:22:11.192Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2021-02-05T13:22:11.192Z] 13:22:11     INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2021-02-05T13:22:11.193Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress
[task 2021-02-05T13:22:11.193Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] OnDocumentLoad triggering AfterOnLoadScripts
[task 2021-02-05T13:22:11.194Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] FromChildAfterPaintListener from about:blank
[task 2021-02-05T13:22:11.195Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] FromChildAfterPaintListener from about:blank
[task 2021-02-05T13:22:11.195Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] FromChildAfterPaintListener from about:blank
[task 2021-02-05T13:22:11.196Z] 13:22:11     INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2021-02-05T13:22:11.197Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] AfterOnLoadScripts belatedly entering WaitForTestEnd
[task 2021-02-05T13:22:11.197Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] WaitForTestEnd: Adding listeners
[task 2021-02-05T13:22:11.197Z] 13:22:11     INFO - REFTEST INFO | Saved log: Initializing canvas snapshot
[task 2021-02-05T13:22:11.198Z] 13:22:11     INFO - REFTEST INFO | Saved log: [CONTENT] MakeProgress
...```

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows7-32: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691034&startday=2021-02-01&endday=2021-02-07&tree=all

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64-qr: 1
  • debug: 1
• windows7-32: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691034&startday=2021-02-15&endday=2021-02-21&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows7-32: 1
  • debug: 1
• windows10-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691034&startday=2021-02-22&endday=2021-02-28&tree=all

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691034&startday=2021-03-01&endday=2021-03-07&tree=all

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows7-32: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691034&startday=2021-03-08&endday=2021-03-14&tree=all

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows7-32: 1
  • debug: 1
• windows10-64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691034&startday=2021-03-15&endday=2021-03-21&tree=all

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• mozilla-central: 1

Platform and build breakdown:

• windows7-32: 1
  • debug: 1
• windows10-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691034&startday=2021-04-05&endday=2021-04-11&tree=all

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64: 1
  • debug: 1
• windows10-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1691034&startday=2021-04-12&endday=2021-04-18&tree=all

Comment 9

[Daniel Holbert [:dholbert]]

This is happening because this test reloads itself right away:

<SCRIPT>
[...]
setTimeout(function(){window.location.reload()}, 200);

This is kind of an anti-pattern for a crashtest. Note the test doesn't have reftest-wait, so we might judge that it's complete (and move on to the next test) before the 200ms timer fires. On the other hand: if we don't judge that it's complete by that time, then we'll reload and queue up some more paints, which then will cause the test-harness to wait, which will then allow for some time for the reloaded test to request another reload, etc. This is why we're hitting the "waiting for pending paint count to reach 0" issue for this test (as reported here) and/or "timed out waiting for test to complete" (bug 1662919).

We should just remove the above-quoted setTimeout. (It's possible this may nerf the test and keep it from testing the issue that it was originally testing -- that's hard to know at this point, given that this test and the issue it was exercising are both so old.)

Comment 10

[Daniel Holbert [:dholbert]]

(Note that bug 1674823 was about a kinda-similar issue with another crashtest from the same set.)

Comment 11

[Daniel Holbert [:dholbert]]

Attachment: Bug 1691034: Remove problematic "auto-reload" behavior from crashtest 370174-3.html. r?#layout-reviewers

This "automatic reload" behavior was probably useful as a PoC for the original
bug, but it's no good in a crashtest, because:

(a) the reload probably doesn't even take effect most of the time, since it's
in a setTimeout that the test is under no obligation to wait for.

(b) if the reload does get a chance to take effect (e.g. on a slower
test-runner where it takes longer for the test harness to judge the test to be
complete), then the test may simply never terminate (or take a long time to
terminate), because each reload causes some more paints, which the test harness
is then forced to wait on; and another reload may arrive before the test
harness checks back to see if we're done painting.

So: let's just remove the auto-reload behavior from this crashtest.

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/eda6b244848e
Remove problematic "auto-reload" behavior from crashtest 370174-3.html. r=emilio

Comment 13

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/eda6b244848e