Intermittent test_cache_https.html | Test timed out

RESOLVED WORKSFORME

Status

()

Core
DOM
RESOLVED WORKSFORME
3 years ago
2 years ago

People

(Reporter: RyanVM, Assigned: bkelly)

Tracking

({intermittent-failure})

Trunk
ARM
Android
intermittent-failure
Points:
---

Firefox Tracking Flags

(firefox41 affected)

Details

(Reporter)

Description

3 years ago
09:19:29 INFO - 263 INFO TEST-START | dom/cache/test/mochitest/test_cache_https.html
09:24:45 INFO - 264 INFO TEST-PASS | dom/cache/test/mochitest/test_cache_https.html | order argument should be valid
09:24:45 INFO - 265 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out. - expected PASS
09:24:45 INFO - 266 INFO TEST-OK | dom/cache/test/mochitest/test_cache_https.html | took 301944ms
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 4

3 years ago
Hmm, all android opt.
Assignee: nobody → bkelly
Status: NEW → ASSIGNED
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)

Comment 10

2 years ago
Geoff, is this something that is caused by Panda devices, or other known Android test instability issues?
Flags: needinfo?(gbrown)
All of these are on Android 4.3, which runs in an Android emulator, running on aws hosts -- not on Pandas.

This does not look like any Android instability issue that I am aware of. Actually most tests are running well in this environment now.

Comparing a logcat from a successful run:

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/27f954e05df928be917628685c94456abd821f400f3c3985bfecf0292442101b43553e21186e0d63822e0974ba6f914522c03bebc00ec1dd76b72e1bdb7efef6

08-05 07:45:46.680   775   795 I GeckoDump: ⰲ겿{"action":"test_start","time":1438785946683,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html"}ⰲ겿
08-05 07:45:46.920   282   283 D dalvikvm: GC_CONCURRENT freed 717K, 37% free 5632K/8820K, paused 23ms+46ms, total 499ms
08-05 07:45:50.820   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785950822,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"order argument should be valid","status":"PASS"}ⰲ겿
08-05 07:45:50.910   775   836 I Gecko   : 
08-05 07:45:50.910   775   836 I Gecko   : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
08-05 07:45:50.910   775   836 I Gecko   : 
08-05 07:45:50.930   775   836 I Gecko   : 
08-05 07:45:50.930   775   836 I Gecko   : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
08-05 07:45:50.930   775   836 I Gecko   : 
08-05 07:45:51.242   775   795 W GeckoConsole: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/dom/cache/test/mochitest/test_cache_https.html" line: 0}]
08-05 07:45:58.700   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785958702,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Correct context for messages received on the worker","status":"PASS"}ⰲ겿
08-05 07:45:58.710   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785958709,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Worker: true: Cache entry should be deleted","status":"PASS"}ⰲ겿
08-05 07:45:58.850   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785958823,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Correct context for messages received on the worker","status":"PASS"}ⰲ겿
08-05 07:45:58.870   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785958860,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Worker: true: Cache entry should be deleted","status":"PASS"}ⰲ겿
08-05 07:45:58.880   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785958882,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Correct context for messages received on the worker","status":"PASS"}ⰲ겿
08-05 07:45:58.900   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785958893,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Worker: true: Cache should be deleted","status":"PASS"}ⰲ겿
08-05 07:45:58.910   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785958911,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Correct context for messages received on the worker","status":"PASS"}ⰲ겿
08-05 07:46:03.580   775   795 W GeckoConsole: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/dom/cache/test/mochitest/message_receiver.html" line: 0}]
08-05 07:46:04.730   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785964735,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"ServiceWorker: true: Cache entry should be deleted","status":"PASS"}ⰲ겿
08-05 07:46:04.790   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785964794,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"ServiceWorker: true: Cache entry should be deleted","status":"PASS"}ⰲ겿
08-05 07:46:04.870   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785964861,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"ServiceWorker: true: Cache should be deleted","status":"PASS"}ⰲ겿
08-05 07:46:05.381   775   795 W GeckoConsole: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/dom/cache/test/mochitest/frame.html" line: 0}]
08-05 07:46:06.330   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785966329,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Window: true: Cache entry should be deleted","status":"PASS"}ⰲ겿
08-05 07:46:06.360   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785966358,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Window: true: Cache entry should be deleted","status":"PASS"}ⰲ겿
08-05 07:46:06.452   775   795 I GeckoDump: ⰲ겿{"action":"test_status","time":1438785966442,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Window: true: Cache should be deleted","status":"PASS"}ⰲ겿
08-05 07:46:06.741   775   795 I GeckoDump: MEMORY STAT | vsize 757MB | residentFast 190MB | heapAllocated 77MB
08-05 07:46:06.960   775   795 I GeckoDump: ⰲ겿{"action":"test_end","time":1438785966961,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","status":"OK","message":"Finished in 20277ms","extra":{"runtime":20277}}ⰲ겿

...to a failure:

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/fx-team/sha512/a30e63c68264dfeaa5ea5375fbc0ef735abeb80163b58e7162cf110cdc8936eea36128ceb8f71e8c89e27ac0d6774e53bf7340c177d9e337e40df348d8385e9f

07-23 05:55:35.870   793   813 I GeckoDump: ⰲ겿{"action":"test_start","time":1437656135872,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html"}ⰲ겿
07-23 05:55:38.361   793   813 I GeckoDump: ⰲ겿{"action":"test_status","time":1437656138359,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"order argument should be valid","status":"PASS"}ⰲ겿
07-23 05:55:38.430   793   854 I Gecko   : 
07-23 05:55:38.430   793   854 I Gecko   : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
07-23 05:55:38.430   793   854 I Gecko   : 
07-23 05:55:38.451   793   854 I Gecko   : 
07-23 05:55:38.451   793   854 I Gecko   : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
07-23 05:55:38.451   793   854 I Gecko   : 
07-23 05:55:38.710   793   813 W GeckoConsole: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/dom/cache/test/mochitest/test_cache_https.html" line: 0}]
...
(unrelated idle activity)
...
07-23 06:00:37.780   793   813 I GeckoDump: ⰲ겿{"action":"test_status","time":1437656437764,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","subtest":"Test timed out.","status":"FAIL","expected":"PASS","stack":"    reportError@SimpleTest/TestRunner.js:334:7\n    TestRunner._checkForHangs@SimpleTest/TestRunner.js:354:7\n"}ⰲ겿
07-23 06:00:38.930   793   813 I GeckoDump: MEMORY STAT | vsize 710MB | residentFast 183MB | heapAllocated 46MB
07-23 06:00:39.020   793   813 I GeckoDump: ⰲ겿{"action":"test_end","time":1437656439013,"thread":"","js_source":"TestRunner","pid":null,"source":"mochitest","test":"/tests/dom/cache/test/mochitest/test_cache_https.html","status":"OK","message":"Finished in 303138ms","extra":{"runtime":303138}}ⰲ겿

In the failed cases, the test never gets to "Correct context for messages received on the worker" -- http://hg.mozilla.org/mozilla-central/annotate/b12a261ee32e/dom/cache/test/mochitest/worker_driver.js#l34
Flags: needinfo?(gbrown)

Comment 12

2 years ago
That smells a lot like the worker not starting up... :(
Comment hidden (Treeherder Robot)
(Assignee)

Comment 14

2 years ago
This hasn't happened in a month.
Status: ASSIGNED → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.