Closed Bug 1045153 Opened 6 years ago Closed 2 years ago

Frequent test_bug866575.html | application timed out after 450.0 seconds with no output

Categories

(Core :: Canvas: 2D, defect)

ARM
Gonk (Firefox OS)
defect
Not set

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: RyanVM, Unassigned)

References

()

Details

(Keywords: intermittent-failure)

This appears to have started across all trunk branches when bug 946065 merged around today. I suspect that's the "cause". Martijn - that SpecialPowers error looks maybe related? I wonder if prior to the reorganizing, the test was picking up state from other tests and isn't anymore, causing the failures. Anyway, given the frequency, I'm going to disable the test for now while this is investigated.

https://tbpl.mozilla.org/php/getParsedLog.php?id=44718508&tree=Mozilla-Central

b2g_emulator_vm mozilla-central debug test mochitest-debug-7 on 2014-07-28 07:52:37 PDT for push 70b3fc807a70
slave: tst-linux64-spot-1139

08:32:11     INFO -  1551 INFO TEST-START | /tests/dom/canvas/test/test_bug866575.html
08:32:11     INFO -  1552 INFO [Child 729] WARNING: Failed to retarget HTML data delivery to the parser thread.: file ../../../gecko/parser/html/nsHtml5StreamParser.cpp, line 947
08:32:29     INFO -  1553 INFO ############ ErrorPage.js
08:32:29     INFO -  1554 INFO [Parent 663] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204
08:32:29     INFO -  1555 INFO [Parent 663] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204
08:32:29     INFO -  1556 INFO [Parent 663] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204
08:32:29     INFO -  1557 INFO [Parent 663] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204
08:32:29     INFO -  1558 INFO [Parent 663] WARNING: NS_ENSURE_TRUE(mRegistered) failed: file ../../../gecko/dom/telephony/ipc/TelephonyParent.cpp, line 94
08:32:29     INFO -  1559 INFO [Parent 663] WARNING: NS_ENSURE_TRUE(mCallback) failed: file ../../../../gecko/content/base/src/nsFrameMessageManager.cpp, line 669
08:32:29     INFO -  1560 INFO System JS : ERROR chrome://specialpowers/content/SpecialPowersObserver.js:96 - NS_ERROR_NOT_INITIALIZED: Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIMessageSender.sendAsyncMessage]
08:40:01     INFO -  DeviceRunner TEST-UNEXPECTED-FAIL | /tests/dom/canvas/test/test_bug866575.html | application timed out after 450.0 seconds with no output
08:40:01     INFO -  1561 INFO Stopping web server
08:41:05     INFO -  1562 INFO Stopping web socket server
08:41:05     INFO -  1563 INFO Stopping ssltunnel
08:41:05     INFO -  1564 INFO runtestsb2g.py | Running tests: end.
08:41:05     INFO -  1565 INFO SUITE-END | took 2395s
Disable the test on B2G debug:
https://hg.mozilla.org/mozilla-central/rev/9df0fa90ab34
Whiteboard: [test disabled on B2G debug][leave open]
The test itself is very simple, it doesn't contain anything SpecialPowers related itself.
It does create a very wide canvas, see: canvas1.width = "306368"
So I guess this is causing an oom situation or something, which somehow triggers the SpecialPowers error.

One thing that strikes me as add in the logs:
08:32:09     INFO -  1549 INFO TEST-OK | /tests/dom/canvas/test/test_bug856472.html | took 3723ms
08:32:10     INFO -  1550 INFO [Child 729] WARNING: Failed to retarget HTML data delivery to the parser thread.: file ../../../gecko/parser/html/nsHtml5StreamParser.cpp, line 947
08:32:11     INFO -  1551 INFO TEST-START | /tests/dom/canvas/test/test_bug866575.html

The INFO TEST-OK message is shown before the TEST-START message, afaik, TEST-OK should always be shown after the  TEST-START message.
I guess this is somehow triggered by this "very large canvas" test.
One way of fixing this perhaps, is to change the test do use SimpleTest.waitForExplicitFinish and SimpleTest.finish. 

(In reply to Martijn Wargers [:mwargers] (QA) from comment #14)
> One thing that strikes me as add in the logs:
> 08:32:09     INFO -  1549 INFO TEST-OK |
> /tests/dom/canvas/test/test_bug856472.html | took 3723ms
> 08:32:10     INFO -  1550 INFO [Child 729] WARNING: Failed to retarget HTML
> data delivery to the parser thread.: file
> ../../../gecko/parser/html/nsHtml5StreamParser.cpp, line 947
> 08:32:11     INFO -  1551 INFO TEST-START |
> /tests/dom/canvas/test/test_bug866575.html
> 
> The INFO TEST-OK message is shown before the TEST-START message, afaik,
> TEST-OK should always be shown after the  TEST-START message.
> I guess this is somehow triggered by this "very large canvas" test.

Sorry, this part of the comment was wrong, those are different tests.
Some more log info:
08:41:19     INFO -  07-28 15:32:10.816 I/GeckoDump(  729): ⰲ겿{"action":"test_start","time":1406561530807,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/canvas/test/test_bug866575.html"}ⰲ겿
08:41:19     INFO -  07-28 15:32:11.337 I/Gecko   (  729): ++DOMWINDOW == 31 (0x440a14d0) [pid = 729] [serial = 412] [outer = 0x4409dca0]
08:41:19     INFO -  07-28 15:32:11.597 I/Gecko   (  729): [Child 729] WARNING: Failed to retarget HTML data delivery to the parser thread.: file ../../../gecko/parser/html/nsHtml5StreamParser.cpp, line 947
08:41:19     INFO -  07-28 15:32:28.247 V/EmulatedCamera_CallbackNotifier(   40): disableMessage: msg_type = 0xffff
08:41:19     INFO -  07-28 15:32:28.247 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_ERROR
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_SHUTTER
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_FOCUS
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_ZOOM
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_PREVIEW_FRAME
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_VIDEO_FRAME
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_POSTVIEW_FRAME
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_RAW_IMAGE
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_COMPRESSED_IMAGE
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_RAW_IMAGE_NOTIFY
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40):     CAMERA_MSG_PREVIEW_METADATA
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_CallbackNotifier(   40): **** Currently enabled messages:
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_Camera(   40): doStopPreview
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_Camera(   40): cancelPicture
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_Camera(   40): releaseCamera
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_Camera(   40): doStopPreview
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_FakeDevice(   40): disconnectDevice
08:41:19     INFO -  07-28 15:32:28.257 I/CameraService(   40): Destroying camera 0
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_Camera(   40): closeCamera
08:41:19     INFO -  07-28 15:32:28.257 V/EmulatedCamera_Camera(   40): doStopPreview
08:41:19     INFO -  07-28 15:32:28.347 W/AudioFlinger(   40): session id 34 not found for pid 40
08:41:19     INFO -  07-28 15:32:28.367 W/AudioFlinger(   40): session id 35 not found for pid 40
08:41:19     INFO -  07-28 15:32:28.447 I/Gecko   (  663):
08:41:19     INFO -  07-28 15:32:28.447 I/Gecko   (  663): ###!!! [Parent][MessageChannel] Error: Channel error: cannot send/recv
08:41:19     INFO -  07-28 15:32:28.447 I/Gecko   (  663):
08:41:19     INFO -  07-28 15:32:28.816 I/Gecko   (  663): ############ ErrorPage.js
08:41:19     INFO -  07-28 15:32:28.957 I/Gecko   (  663): [Parent 663] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204
08:41:19     INFO -  07-28 15:32:28.967 I/Gecko   (  663): [Parent 663] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204
08:41:19     INFO -  07-28 15:32:28.967 I/Gecko   (  663): [Parent 663] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204
08:41:19     INFO -  07-28 15:32:28.967 I/Gecko   (  663): [Parent 663] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204
08:41:19     INFO -  07-28 15:32:28.987 I/Gecko   (  663): [Parent 663] WARNING: NS_ENSURE_TRUE(mRegistered) failed: file ../../../gecko/dom/telephony/ipc/TelephonyParent.cpp, line 94
08:41:19     INFO -  07-28 15:32:29.147 I/Gecko   (  663): [Parent 663] WARNING: NS_ENSURE_TRUE(mCallback) failed: file ../../../../gecko/content/base/src/nsFrameMessageManager.cpp, line 669
08:41:19  WARNING -  07-28 15:32:29.197 E/GeckoConsole(  663): [JavaScript Error: "NS_ERROR_NOT_INITIALIZED: Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIMessageSender.sendAsyncMessage]" {file: "chrome://specialpowers/content/SpecialPowersObserver.js" line: 96}]
08:41:19     INFO -  07-28 15:32:29.327 E/OomLogger(  663): [Kill]: select 729 (Mochitest), adj 2, size 111438, to kill
08:41:19     INFO -  07-28 15:32:29.327 E/OomLogger(  663): [Kill]: send sigkill to 729 (Mochitest), adj 2, size 111438
08:41:19     INFO -  07-28 15:39:59.427 I/ServiceManager(   33): service 'media.resource_manager' died
08:41:19     INFO -  07-28 15:39:59.427 I/ServiceManager(   33): service 'permission' died

So it looks like the mochitest app was killed, because of oom.
This same test is the only thing blocking generational garbage collection from being enabled on B2G (bug 1022794). Enabling ggc turns this test into a permafail, though I did not have any OOMs logged for it and I don't believe it was OOMing. The logs for the above bug have expired, so I just kicked off another push at https://tbpl.mozilla.org/?tree=Try&rev=bbd13528e909

Given the different OOM behavior, I'm not sure it's really failing for the same reasons. One option would be to land GGC now, and fix that failure before re-enabling instead of spending time on this one. I, of course, like that approach best. :-)
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Whiteboard: [test disabled on B2G debug][leave open]
You need to log in before you can comment on or make changes to this bug.