1172133 - Intermittent test_cache_https.html | Test timed out

Status: RESOLVED WORKSFORME

(Core :: DOM: Core & HTML, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

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 1

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=10486986
repository: mozilla-inbound
start_time: 2015-06-05T08:25:16
who: rvandermeulen[at]mozilla[dot]com
machine: tst-linux64-spot-1891
buildname: Android 4.3 armv7 API 11+ mozilla-inbound opt test mochitest-4
revision: 0f448c718d9f

265 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out. - expected PASS

Comment 2

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=fx-team&job_id=3390150
repository: fx-team
start_time: 2015-06-10T00:47:50
who: tomcat[at]mozilla[dot]com
machine: tst-linux64-spot-1731
buildname: Android 4.3 armv7 API 11+ fx-team opt test mochitest-4
revision: fd60bc4207c6

263 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out. - expected PASS

Comment 3

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=10604706
repository: mozilla-inbound
start_time: 2015-06-10T08:56:52
who: rvandermeulen[at]mozilla[dot]com
machine: tst-linux64-spot-173
buildname: Android 4.3 armv7 API 11+ mozilla-inbound opt test mochitest-4
revision: d8b1e08c2941

173 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out. - expected PASS

Comment 4

[Ben Kelly [:bkelly, not reviewing]]

Hmm, all android opt.

Comment 5

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=10863424
repository: mozilla-inbound
start_time: 2015-06-16T18:18:12
who: philringnalda[at]gmail[dot]com
machine: tst-linux64-spot-1152
buildname: Android 4.3 armv7 API 11+ mozilla-inbound opt test mochitest-4
revision: eefb95916e40

169 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out. - expected PASS

Comment 6

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=11781091
repository: mozilla-inbound
start_time: 2015-07-16T12:56:08
who: wkocher[at]mozilla[dot]com
machine: tst-linux64-spot-1849
buildname: Android 4.3 armv7 API 11+ mozilla-inbound opt test mochitest-4
revision: 719d9b099457

157 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out.

Comment 7

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=11887818
repository: mozilla-inbound
start_time: 2015-07-19T21:26:41
who: tomcat[at]mozilla[dot]com
machine: tst-linux64-spot-1218
buildname: Android 4.3 armv7 API 11+ mozilla-inbound opt test mochitest-4
revision: accaecdd989d

161 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out.

Comment 8

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=fx-team&job_id=3893297
repository: fx-team
start_time: 2015-07-23T04:52:18
who: rvandermeulen[at]mozilla[dot]com
machine: tst-linux64-spot-1192
buildname: Android 4.3 armv7 API 11+ fx-team opt test mochitest-4
revision: 5fc3405af99d

169 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out.

Comment 9

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=fx-team&job_id=4010103
repository: fx-team
start_time: 2015-07-31T00:47:21
who: tomcat[at]mozilla[dot]com
machine: tst-linux64-spot-749
buildname: Android 4.3 armv7 API 11+ fx-team opt test mochitest-4
revision: 78a8ee2b72bb

185 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out.

Comment 10

[(no longer active)]

Geoff, is this something that is caused by Panda devices, or other known Android test instability issues?

Comment 11

[Geoff Brown [: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

Comment 12

[(no longer active)]

That smells a lot like the worker not starting up... :(

Comment 13

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=12891990
repository: mozilla-inbound
start_time: 2015-08-14T10:20:17
who: rvandermeulen[at]mozilla[dot]com
machine: tst-linux64-spot-1280
buildname: Android 4.3 armv7 API 11+ mozilla-inbound opt test mochitest-4
revision: 4c245c476379

189 INFO TEST-UNEXPECTED-FAIL | dom/cache/test/mochitest/test_cache_https.html | Test timed out.

Comment 14

[Ben Kelly [:bkelly, not reviewing]]

This hasn't happened in a month.