Intermittent image/test/mochitest/test_discardAnimatedImage.html | Test timed out.

RESOLVED FIXED in Firefox 68

Status

()

defect
RESOLVED FIXED
2 years ago
Last month

People

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

Tracking

(Regressed 1 bug, {intermittent-failure})

unspecified
mozilla68
Points:
---

Firefox Tracking Flags

(firefox68 fixed)

Details

(Whiteboard: [gfx-noted][stockwell unknown])

Attachments

(1 attachment)

Whiteboard: [gfx-noted]
Bulk priority update of open intermittent test failure bugs. 

P3 => P5

https://bugzilla.mozilla.org/show_bug.cgi?id=1381960
Priority: P3 → P5
https://wiki.mozilla.org/Bugmasters#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 2 years agoLast year
Resolution: --- → INCOMPLETE

There are 27 total failures in the last 7 days on linux, osx and windows

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=232937185&repo=mozilla-central&lineNumber=20222

[task 2019-03-09T23:03:49.115Z] 23:03:49 INFO - TEST-START | image/test/mochitest/test_discardAnimatedImage.html
[task 2019-03-09T23:03:49.211Z] 23:03:49 INFO - GECKO(3208) | [Parent 3208, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4104
[task 2019-03-09T23:03:49.288Z] 23:03:49 INFO - GECKO(3208) | ++DOMWINDOW == 40 (0x7f91b2f9bc00) [pid = 3310] [serial = 187] [outer = 0x7f91b29892e0]
[task 2019-03-09T23:03:49.325Z] 23:03:49 INFO - GECKO(3208) | --DOMWINDOW == 39 (0x7f91b10f1000) [pid = 3310] [serial = 167] [outer = (nil)] [url = http://mochi.test:8888/tests/image/test/mochitest/test_bug865919.html]
[task 2019-03-09T23:03:49.326Z] 23:03:49 INFO - GECKO(3208) | --DOMWINDOW == 38 (0x7f91b29f0c00) [pid = 3310] [serial = 172] [outer = (nil)] [url = http://mochi.test:8888/tests/image/test/mochitest/bug89419-iframe.html]
[task 2019-03-09T23:03:49.326Z] 23:03:49 INFO - GECKO(3208) | --DOMWINDOW == 37 (0x7f91b29f2400) [pid = 3310] [serial = 171] [outer = (nil)] [url = http://mochi.test:8888/tests/image/test/mochitest/bug89419-iframe.html]

task 2019-03-09T23:09:15.372Z] 23:09:15 INFO - TEST-PASS | image/test/mochitest/test_discardAnimatedImage.html | got image discard
[task 2019-03-09T23:09:15.374Z] 23:09:15 INFO - TEST-PASS | image/test/mochitest/test_discardAnimatedImage.html | got image discard
[task 2019-03-09T23:09:15.375Z] 23:09:15 INFO - Buffered messages finished
[task 2019-03-09T23:09:15.375Z] 23:09:15 INFO - TEST-UNEXPECTED-FAIL | image/test/mochitest/test_discardAnimatedImage.html | Test timed out.
[task 2019-03-09T23:09:15.375Z] 23:09:15 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-03-09T23:09:15.376Z] 23:09:15 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-03-09T23:09:15.376Z] 23:09:15 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2019-03-09T23:09:15.376Z] 23:09:15 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.376Z] 23:09:15 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.377Z] 23:09:15 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.377Z] 23:09:15 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.378Z] 23:09:15 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.379Z] 23:09:15 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.379Z] 23:09:15 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.380Z] 23:09:15 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.380Z] 23:09:15 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.380Z] 23:09:15 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.381Z] 23:09:15 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.382Z] 23:09:15 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.382Z] 23:09:15 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.383Z] 23:09:15 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.383Z] 23:09:15 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.383Z] 23:09:15 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.384Z] 23:09:15 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-09T23:09:15.384Z] 23:09:15 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:381:20
[task 2019-03-09T23:09:15.384Z] 23:09:15 INFO - promise callback
TestRunner.runTests@SimpleTest/TestRunner.js:368:50
[task 2019-03-09T23:09:15.385Z] 23:09:15 INFO - RunSet.runtests@SimpleTest/setup.js:201:14
[task 2019-03-09T23:09:15.385Z] 23:09:15 INFO - RunSet.runall@SimpleTest/setup.js:180:12
[task 2019-03-09T23:09:15.385Z] 23:09:15 INFO - hookupTests@SimpleTest/setup.js:273:12
[task 2019-03-09T23:09:15.385Z] 23:09:15 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
[task 2019-03-09T23:09:15.386Z] 23:09:15 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
[task 2019-03-09T23:09:15.387Z] 23:09:15 INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
[task 2019-03-09T23:09:15.387Z] 23:09:15 INFO - hookup@SimpleTest/setup.js:253:5
[task 2019-03-09T23:09:15.387Z] 23:09:15 INFO - EventHandlerNonNull
@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2019-03-09T23:09:15.927Z] 23:09:15 INFO - GECKO(3208) | MEMORY STAT | vsize 1515MB | residentFast 135MB | heapAllocated 12MB
[task 2019-03-09T23:09:15.928Z] 23:09:15 INFO - TEST-OK | image/test/mochitest/test_discardAnimatedImage.html | took 326814ms

Andrew can you assign someone to take a look at this?

Flags: needinfo?(aosmond)
Whiteboard: [gfx-noted] → [gfx-noted][stockwell needswork:owner]

Over the last 7 days there have been 32 failures present on this log. These happen on windows10-64-qr, windows10-64-pgo-qr, windows10-64, osx-10-10, linux64-qr, linux64, linux32

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=235634385&repo=autoland&lineNumber=7054

The test times out waiting for the discard notification of an image or images. The reason they don't get discarded is they have a lock count of 1. I tried giving the images a unique query string so this test was the only place they were used, that seemed to reduce the frequency about 4x, but it still happens. So some weird bug where images get locked and stay locked (but shouldn't be).

In the last 7 days, there have been 37 failures.

Most of the failures are on linux32 and linux64, linux64-qr, linux64-shippable, osx-10-10, osx-10-10-shippable and windows10-64.
Affected build types: debug, opt, asan.

An example of a recent log file:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=235804227&repo=autoland&lineNumber=3685

And the relevant part of the log:
[task 2019-03-25T10:21:02.090Z] 10:21:02 INFO - TEST-PASS | image/test/mochitest/test_discardAnimatedImage.html | got image discard
[task 2019-03-25T10:21:02.091Z] 10:21:02 INFO - Buffered messages finished
[task 2019-03-25T10:21:02.094Z] 10:21:02 INFO - TEST-UNEXPECTED-FAIL | image/test/mochitest/test_discardAnimatedImage.html | Test timed out.
[task 2019-03-25T10:21:02.095Z] 10:21:02 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-03-25T10:21:02.095Z] 10:21:02 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-03-25T10:21:02.096Z] 10:21:02 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2019-03-25T10:21:02.096Z] 10:21:02 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.097Z] 10:21:02 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.097Z] 10:21:02 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.098Z] 10:21:02 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.098Z] 10:21:02 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.098Z] 10:21:02 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.099Z] 10:21:02 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.099Z] 10:21:02 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.100Z] 10:21:02 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.100Z] 10:21:02 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.101Z] 10:21:02 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.101Z] 10:21:02 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.101Z] 10:21:02 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.102Z] 10:21:02 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.102Z] 10:21:02 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.103Z] 10:21:02 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-03-25T10:21:02.103Z] 10:21:02 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:381:20
[task 2019-03-25T10:21:02.103Z] 10:21:02 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:368:50
[task 2019-03-25T10:21:02.104Z] 10:21:02 INFO - RunSet.runtests@SimpleTest/setup.js:201:14
[task 2019-03-25T10:21:02.104Z] 10:21:02 INFO - RunSet.runall@SimpleTest/setup.js:180:12
[task 2019-03-25T10:21:02.104Z] 10:21:02 INFO - hookupTests@SimpleTest/setup.js:273:12
[task 2019-03-25T10:21:02.104Z] 10:21:02 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
[task 2019-03-25T10:21:02.104Z] 10:21:02 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
[task 2019-03-25T10:21:02.104Z] 10:21:02 INFO - EventHandlerNonNull
getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
[task 2019-03-25T10:21:02.104Z] 10:21:02 INFO - hookup@SimpleTest/setup.js:253:5
[task 2019-03-25T10:21:02.104Z] 10:21:02 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1

Andrew, as you are the triage owner of this component, could you please take a look at this?
Thank you!

I've been debugging this via try, see comment 28. But didn't have any time last week to do more try pushes. I'll try to pick this back up soon.

I figured this out, hopefully patch tomorrow.

Timothy, that's great to hear, thank you.

Flags: needinfo?(aosmond)

This has failed 35 times in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-09&endday=2019-04-16&tree=trunk&bug=1377457

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=240515931&repo=autoland

[task 2019-04-16T00:33:19.147Z] 00:33:19 INFO - TEST-PASS | image/test/mochitest/test_discardAnimatedImage.html | got image discard
[task 2019-04-16T00:33:19.148Z] 00:33:19 INFO - Buffered messages finished
[task 2019-04-16T00:33:19.151Z] 00:33:19 INFO - TEST-UNEXPECTED-FAIL | image/test/mochitest/test_discardAnimatedImage.html | Test timed out.
[task 2019-04-16T00:33:19.152Z] 00:33:19 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-04-16T00:33:19.153Z] 00:33:19 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-04-16T00:33:19.153Z] 00:33:19 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2019-04-16T00:33:19.153Z] 00:33:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.154Z] 00:33:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.154Z] 00:33:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.155Z] 00:33:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.156Z] 00:33:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.156Z] 00:33:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.157Z] 00:33:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.157Z] 00:33:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.158Z] 00:33:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.158Z] 00:33:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.159Z] 00:33:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.159Z] 00:33:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.159Z] 00:33:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.160Z] 00:33:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.160Z] 00:33:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.162Z] 00:33:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-16T00:33:19.162Z] 00:33:19 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:381:20
[task 2019-04-16T00:33:19.163Z] 00:33:19 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:368:50
[task 2019-04-16T00:33:19.163Z] 00:33:19 INFO - RunSet.runtests@SimpleTest/setup.js:201:14
[task 2019-04-16T00:33:19.163Z] 00:33:19 INFO - RunSet.runall@SimpleTest/setup.js:180:12
[task 2019-04-16T00:33:19.163Z] 00:33:19 INFO - hookupTests@SimpleTest/setup.js:273:12
[task 2019-04-16T00:33:19.164Z] 00:33:19 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
[task 2019-04-16T00:33:19.164Z] 00:33:19 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
[task 2019-04-16T00:33:19.165Z] 00:33:19 INFO - EventHandlerNonNull
getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
[task 2019-04-16T00:33:19.165Z] 00:33:19 INFO - hookup@SimpleTest/setup.js:253:5
[task 2019-04-16T00:33:19.165Z] 00:33:19 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2019-04-16T00:33:19.543Z] 00:33:19 INFO - GECKO(2916) | MEMORY STAT | vsize 2579MB | residentFast 135MB | heapAllocated 11MB
[task 2019-04-16T00:33:19.559Z] 00:33:19 INFO - TEST-OK | image/test/mochitest/test_discardAnimatedImage.html | took 306308ms

Timothy, any progress on this? Thank you.

Flags: needinfo?(tnikkel)

There are 27 total failures in the last 7 days on multiple platforms: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-17&endday=2019-04-24&tree=trunk&bug=1377457

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=242172785&repo=mozilla-central&lineNumber=20185

[task 2019-04-23T23:23:13.197Z] 23:23:13 INFO - TEST-START | image/test/mochitest/test_discardAnimatedImage.html
[task 2019-04-23T23:28:19.294Z] 23:28:19 INFO - Buffered messages finished
[task 2019-04-23T23:28:19.295Z] 23:28:19 INFO - TEST-UNEXPECTED-FAIL | image/test/mochitest/test_discardAnimatedImage.html | Test timed out.
[task 2019-04-23T23:28:19.295Z] 23:28:19 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-04-23T23:28:19.295Z] 23:28:19 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-04-23T23:28:19.295Z] 23:28:19 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2019-04-23T23:28:19.296Z] 23:28:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.296Z] 23:28:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.296Z] 23:28:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.296Z] 23:28:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.297Z] 23:28:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.297Z] 23:28:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.297Z] 23:28:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.297Z] 23:28:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.297Z] 23:28:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.298Z] 23:28:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.298Z] 23:28:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.298Z] 23:28:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.298Z] 23:28:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.299Z] 23:28:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.299Z] 23:28:19 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.299Z] 23:28:19 INFO - setTimeout handler
TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2019-04-23T23:28:19.299Z] 23:28:19 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:381:20
[task 2019-04-23T23:28:19.300Z] 23:28:19 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:368:50
[task 2019-04-23T23:28:19.300Z] 23:28:19 INFO - RunSet.runtests@SimpleTest/setup.js:201:14
[task 2019-04-23T23:28:19.300Z] 23:28:19 INFO - RunSet.runall@SimpleTest/setup.js:180:12
[task 2019-04-23T23:28:19.300Z] 23:28:19 INFO - hookupTests@SimpleTest/setup.js:273:12
[task 2019-04-23T23:28:19.301Z] 23:28:19 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
[task 2019-04-23T23:28:19.301Z] 23:28:19 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
[task 2019-04-23T23:28:19.301Z] 23:28:19 INFO - EventHandlerNonNull
getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
[task 2019-04-23T23:28:19.301Z] 23:28:19 INFO - hookup@SimpleTest/setup.js:253:5
[task 2019-04-23T23:28:19.302Z] 23:28:19 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2019-04-23T23:28:19.722Z] 23:28:19 INFO - GECKO(2934) | MEMORY STAT | vsize 2582MB | residentFast 133MB | heapAllocated 11MB

This was observed in an intermittent failure of image/test/mochitest/test_discardAnimatedImage.html. What happened was:

  1. Document::MaybePreLoadImage was called for the images in the test.
  2. imgRequest::OnDataAvailable is called on at least one of the images. This creates the RasterImage, so any proxy for this imgRequest will now return the image via GetImage(). imgRequest::OnDataAvailable also queues the FinishPreparingForNewPartRunnable back to the main thread to call OnImageAvailable on the progress tracker on the main thread.
  3. We get the actual LoadImage calls for the images of the document. We create new proxies for the existing imgRequests. imgRequestProxy::Init calls mBehaviour->SetOwner(aOwner), which sets mOwnerHasImage to true because the progress tracker has an mImage (the one we created above).
  4. We get a call to LockImage, this gets forwarded to the RasterImage because mOwnerHasImage is true and we can access the image.
  5. The FinishPreparingForNewPartRunnable finally runs on the main thread. The OnImageAvailable notification from the progress tracker ends up in imgRequestProxy::SetHasImage. imgRequestProxy::SetHasImage applies our local count mLockCount to the RasterImage, even though we've already forwarded one of those LockImage calls to the image. LockImage calls are now unbalanced and the image will always remain locked.

The fix is simple. Only apply the Lock/Unlock calls if the FinishPreparingForNewPartRunnable has hit the main thread (ie ignore an image we can access until this happens).

Assignee: nobody → tnikkel
Flags: needinfo?(tnikkel)
Pushed by tnikkel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/5acce9aaceb9
Only apply locks to the image if SetHasImage has been called. r=aosmond
Status: REOPENED → RESOLVED
Closed: Last year3 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla68
Regressions: 1548846
You need to log in before you can comment on or make changes to this bug.