Closed Bug 1282207 Opened 9 years ago Closed 8 years ago

Intermittent dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | application timed out after 330 seconds with no output

Categories

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

Product:
Core
Component:
DOM: Core & HTML
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1325942

People

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

References

Details

(Whiteboard: [stockwell fixed])

Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Assignee: nobody → sphink
Looks to be another slowdown from bug 1335751.
Blocks: 1335751
Whiteboard: [stockwell needswork]
This doesn't seem to be android specific, more linux32-debug (e10s || non-e10s). The quick win is to skip this on linux32/debug, but lets leave that as a last resort. from a linux32/debug log: https://queue.taskcluster.net/v1/task/QvcIEdpaQSOzA4IhoZ4gug/runs/0/artifacts/public/logs/live_backing.log we have this related to the test: [task 2017-03-13T06:33:51.501679Z] 06:33:50 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: <res>hello pass</res> [task 2017-03-13T06:33:51.503865Z] 06:33:50 INFO - === <res>hello pass</res> [task 2017-03-13T06:33:51.505704Z] 06:33:50 INFO - : wrong responseText in test for ({pass:1, method:"GET", responseHeaders:{'x-my-header':"x header", 'y-my-header':"y header"}, exposeHeaders:" , ,,y-my-header,z-my-header, ", expectedResponseHeaders:["y-my-header"]}) [task 2017-03-13T06:33:51.508288Z] 06:33:50 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: <res>hello pass</res> [task 2017-03-13T06:33:51.509780Z] 06:33:50 INFO - === <res>hello pass</res> [task 2017-03-13T06:33:51.511977Z] 06:33:50 INFO - : wrong responseText in test for ({pass:1, method:"GET", responseHeaders:{'Cache-Control':"cacheControl header", 'Content-Language':"contentLanguage header", Expires:"expires header", 'Last-Modified':"lastModified header", Pragma:"pragma header", Unexpected:"unexpected header"}, expectedResponseHeaders:["Cache-Control", "Content-Language", "Content-Type", "Expires", "Last-Modified", "Pragma"]}) [task 2017-03-13T06:33:51.513759Z] 06:33:50 INFO - Buffered messages logged at 06:28:06 [task 2017-03-13T06:33:51.516465Z] 06:33:50 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: true: Expected test failure for ({pass:0, method:"GET", headers:{'x-my-header':""}}) [task 2017-03-13T06:33:51.519876Z] 06:33:50 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: true: Exception should be TypeError for ({pass:0, method:"GET", headers:{'x-my-header':""}}) [task 2017-03-13T06:33:51.520152Z] 06:33:50 INFO - Buffered messages finished [task 2017-03-13T06:33:51.522769Z] 06:33:50 INFO - TEST-UNEXPECTED-TIMEOUT | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | application timed out after 330 seconds with no output [task 2017-03-13T06:33:51.523065Z] 06:33:50 ERROR - Force-terminating active process(es). [task 2017-03-13T06:33:51.523291Z] 06:33:50 INFO - Determining child pids from psutil [task 2017-03-13T06:33:51.523587Z] 06:33:50 INFO - Found child pids: [1860] [task 2017-03-13T06:33:51.523844Z] 06:33:50 INFO - Killing process: 1860 [task 2017-03-13T06:33:51.525113Z] 06:33:50 INFO - TEST-INFO | started process screentopng [task 2017-03-13T06:33:52.006203Z] 06:33:52 INFO - TEST-INFO | screentopng: exit 0 [task 2017-03-13T06:33:53.488159Z] 06:33:53 INFO - psutil found pid 1860 dead [task 2017-03-13T06:33:53.488557Z] 06:33:53 INFO - Killing process: 1809 [task 2017-03-13T06:33:53.488866Z] 06:33:53 INFO - Not taking screenshot here: see the one that was previously logged [task 2017-03-13T06:33:54.456251Z] 06:33:54 INFO - TEST-INFO | Main app process: exit 6 [task 2017-03-13T06:33:54.456666Z] 06:33:54 INFO - Buffered messages finished [task 2017-03-13T06:33:54.458456Z] 06:33:54 ERROR - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | application terminated with exit code 6 [task 2017-03-13T06:33:54.460600Z] 06:33:54 INFO - runtests.py | Application ran for: 0:13:37.095429 [task 2017-03-13T06:33:54.463015Z] 06:33:54 INFO - zombiecheck | Reading PID log: /tmp/tmpSWtymopidlog [task 2017-03-13T06:33:54.466484Z] 06:33:54 INFO - ==> process 1809 launched child process 1827 [task 2017-03-13T06:33:54.469007Z] 06:33:54 INFO - ==> process 1809 launched child process 1860 [task 2017-03-13T06:33:54.479119Z] 06:33:54 INFO - zombiecheck | Checking for orphan process with PID: 1827 [task 2017-03-13T06:33:54.486198Z] 06:33:54 INFO - zombiecheck | Checking for orphan process with PID: 1860 [task 2017-03-13T06:33:54.492423Z] 06:33:54 INFO - mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmpgY2o3T.mozrunner/minidumps/43422906-174a-3875-029d99cd-6f6f10b2.dmp /home/worker/workspace/build/symbols [task 2017-03-13T06:34:08.322131Z] 06:34:08 INFO - mozcrash Saved minidump as /home/worker/workspace/build/blobber_upload_dir/43422906-174a-3875-029d99cd-6f6f10b2.dmp [task 2017-03-13T06:34:08.326043Z] 06:34:08 INFO - mozcrash Saved app info as /home/worker/workspace/build/blobber_upload_dir/43422906-174a-3875-029d99cd-6f6f10b2.extra [task 2017-03-13T06:34:08.698836Z] 06:34:08 INFO - PROCESS-CRASH | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | application crashed [@ js::MovableCellHasher<js::SavedFrame*>::hash] [task 2017-03-13T06:34:08.701340Z] 06:34:08 INFO - Crash dump filename: /tmp/tmpgY2o3T.mozrunner/minidumps/43422906-174a-3875-029d99cd-6f6f10b2.dmp [task 2017-03-13T06:34:08.703006Z] 06:34:08 INFO - Operating system: Linux [task 2017-03-13T06:34:08.704799Z] 06:34:08 INFO - 0.0.0 Linux 3.13.0-100-generic #147-Ubuntu SMP Tue Oct 18 16:48:51 UTC 2016 x86_64 [task 2017-03-13T06:34:08.706429Z] 06:34:08 INFO - CPU: x86 [task 2017-03-13T06:34:08.708134Z] 06:34:08 INFO - GenuineIntel family 6 model 62 stepping 4 [task 2017-03-13T06:34:08.709707Z] 06:34:08 INFO - 1 CPU [task 2017-03-13T06:34:08.711584Z] 06:34:08 INFO - [task 2017-03-13T06:34:08.713149Z] 06:34:08 INFO - GPU: UNKNOWN [task 2017-03-13T06:34:08.714752Z] 06:34:08 INFO - [task 2017-03-13T06:34:08.716339Z] 06:34:08 INFO - Crash reason: SIGABRT [task 2017-03-13T06:34:08.718021Z] 06:34:08 INFO - Crash address: 0x4a3 [task 2017-03-13T06:34:08.719644Z] 06:34:08 INFO - Process uptime: not available [task 2017-03-13T06:34:08.721116Z] 06:34:08 INFO - [task 2017-03-13T06:34:08.722815Z] 06:34:08 INFO - Thread 0 (crashed) [task 2017-03-13T06:34:08.724696Z] 06:34:08 INFO - 0 libxul.so!js::MovableCellHasher<js::SavedFrame*>::hash [Heap.h:b51aaaafa7bd : 1269 + 0x2] [task 2017-03-13T06:34:08.726466Z] 06:34:08 INFO - eip = 0xf46fea39 esp = 0xffd43400 ebp = 0xffd43458 ebx = 0xf6196914 [task 2017-03-13T06:34:08.728249Z] 06:34:08 INFO - esi = 0xffd435e0 edi = 0xffd4348c eax = 0xe8251478 ecx = 0xf7403bc8 [task 2017-03-13T06:34:08.729897Z] 06:34:08 INFO - edx = 0x00000006 efl = 0x00000282 [task 2017-03-13T06:34:08.731870Z] 06:34:08 INFO - Found by: given as instruction pointer in context [task 2017-03-13T06:34:08.733575Z] 06:34:08 INFO - 1 libxul.so!js::SavedFrame::HashPolicy::hash [SavedStacks.cpp:b51aaaafa7bd : 256 + 0xb] [task 2017-03-13T06:34:08.735239Z] 06:34:08 INFO - eip = 0xf4555960 esp = 0xffd43460 ebp = 0xffd43498 ebx = 0xf6196914 [task 2017-03-13T06:34:08.736819Z] 06:34:08 INFO - esi = 0xffd435cc edi = 0xffd4348c [task 2017-03-13T06:34:08.738430Z] 06:34:08 INFO - Found by: call frame info [task 2017-03-13T06:34:08.740656Z] 06:34:08 INFO - 2 libxul.so!js::SavedStacks::getOrCreateSavedFrame [HashTable.h:b51aaaafa7bd : 1207 + 0xb] [task 2017-03-13T06:34:08.742361Z] 06:34:08 INFO - eip = 0xf457116b esp = 0xffd434a0 ebp = 0xffd43548 ebx = 0xf6196914 [task 2017-03-13T06:34:08.744328Z] 06:34:08 INFO - esi = 0xeced4c70 edi = 0x00000000 [task 2017-03-13T06:34:08.747374Z] 06:34:08 INFO - Found by: call frame info [task 2017-03-13T06:34:08.749050Z] 06:34:08 INFO - 3 libxul.so!js::SavedStacks::adoptAsyncStack [SavedStacks.cpp:b51aaaafa7bd : 1483 + 0x16] [task 2017-03-13T06:34:08.750969Z] 06:34:08 INFO - eip = 0xf4571854 esp = 0xffd43550 ebp = 0xffd439d8 ebx = 0xf6196914 [task 2017-03-13T06:34:08.752707Z] 06:34:08 INFO - esi = 0x00000000 edi = 0x00000000 [task 2017-03-13T06:34:08.755437Z] 06:34:08 INFO - Found by: call frame info [task 2017-03-13T06:34:08.757096Z] 06:34:08 INFO - 4 libxul.so!js::SavedStacks::insertFrames [SavedStacks.cpp:b51aaaafa7bd : 1399 + 0x18] [task 2017-03-13T06:34:08.758784Z] 06:34:08 INFO - eip = 0xf45722d3 esp = 0xffd439e0 ebp = 0xffd43ef8 ebx = 0xf6196914 [task 2017-03-13T06:34:08.760450Z] 06:34:08 INFO - esi = 0x0000003c edi = 0xf7263800 [task 2017-03-13T06:34:08.763472Z] 06:34:08 INFO - Found by: call frame info [task 2017-03-13T06:34:08.765136Z] 06:34:08 INFO - 5 libxul.so!js::SavedStacks::saveCurrentStack [SavedStacks.cpp:b51aaaafa7bd : 1175 + 0x24] [task 2017-03-13T06:34:08.766812Z] 06:34:08 INFO - eip = 0xf4572914 esp = 0xffd43f00 ebp = 0xffd44148 ebx = 0xf6196914 [task 2017-03-13T06:34:08.768500Z] 06:34:08 INFO - esi = 0xeced4c70 edi = 0xf7263800 [task 2017-03-13T06:34:08.770029Z] 06:34:08 INFO - Found by: call frame info [task 2017-03-13T06:34:08.772263Z] 06:34:08 INFO - 6 libxul.so!JS::CaptureCurrentStack [jsapi.cpp:b51aaaafa7bd : 7063 + 0x9] [task 2017-03-13T06:34:08.773998Z] 06:34:08 INFO - eip = 0xf431c131 esp = 0xffd44150 ebp = 0xffd44198 ebx = 0xf6196914 [task 2017-03-13T06:34:08.775971Z] 06:34:08 INFO - esi = 0xf7263800 edi = 0xffd44170 [task 2017-03-13T06:34:08.778672Z] 06:34:08 INFO - Found by: call frame info [task 2017-03-13T06:34:08.780378Z] 06:34:08 INFO - 7 libxul.so!js::PromiseObject::onSettled [Promise.cpp:b51aaaafa7bd : 2636 + 0x5] [task 2017-03-13T06:34:08.782024Z] 06:34:08 INFO - eip = 0xf3f9455a esp = 0xffd441a0 ebp = 0xffd441f8 ebx = 0xf6196914 [task 2017-03-13T06:34:08.783610Z] 06:34:08 INFO - esi = 0xffd442bc edi = 0xf7263800 [task 2017-03-13T06:34:08.785173Z] 06:34:08 INFO - Found by: call frame info [task 2017-03-13T06:34:08.786813Z] 06:34:08 INFO - 8 libxul.so!ResolvePromise [Promise.cpp:b51aaaafa7bd : 581 + 0xf] [task 2017-03-13T06:34:08.788834Z] 06:34:08 INFO - eip = 0xf3f94778 esp = 0xffd44200 ebp = 0xffd44288 ebx = 0xf6196914 [task 2017-03-13T06:34:08.790380Z] 06:34:08 INFO - esi = 0xf7263800 edi = 0xffd44250 [task 2017-03-13T06:34:08.792069Z] 06:34:08 INFO - Found by: call frame info is it possible we are always failing on tests that deal with cross origin?
Flags: needinfo?(sphink)
:wlach, could you try this test with your retrigger with logging toolchain?
Flags: needinfo?(wlachance)
(In reply to Joel Maher ( :jmaher) from comment #10) > :wlach, could you try this test with your retrigger with logging toolchain? Done. Some interesting debug output: https://treeherder.mozilla.org/logviewer.html#?job_id=83774811&repo=try&lineNumber=10464 https://treeherder.mozilla.org/#/jobs?repo=try&revision=f9f1ae807d384f42912547621443e46db90b00f7&selectedJob=83774811 [task 2017-03-14T19:22:09.511598Z] GECKO(1276) | [Child 1331] WARNING: A runnable was posted to a worker that is already shutting down!: file /home/worker/workspace/build/src/dom/workers/WorkerPrivate.cpp, line 2863 [task 2017-03-14T19:22:09.512365Z] GECKO(1276) | [Child 1331] WARNING: Could not dispatch fetch response: file /home/worker/workspace/build/src/dom/fetch/Fetch.cpp, line 414 [task 2017-03-14T19:22:09.514456Z] GECKO(1276) | [Child 1331] WARNING: A runnable was posted to a worker that is already shutting down!: file /home/worker/workspace/build/src/dom/workers/WorkerPrivate.cpp, line 2863 [task 2017-03-14T19:22:10.400730Z] GECKO(1276) | [Child 1331] WARNING: A runnable was posted to a worker that is already shutting down!: file /home/worker/workspace/build/src/dom/workers/WorkerPrivate.cpp, line 2863 [task 2017-03-14T19:22:10.403413Z] GECKO(1276) | [Child 1331] WARNING: Could not dispatch fetch response: file /home/worker/workspace/build/src/dom/fetch/Fetch.cpp, line 414 ... (see log for more details)
Flags: needinfo?(wlachance)
a similar failure is tracked in bug 1284733 for dom/tests/mochitest/fetch/test_fetch_cors.html.
:sfink, this is quite frequent still, we speculated this was related to the gc::grey work- is there work we can do here?
See Also: → 1325942
(In reply to Joel Maher ( :jmaher) from comment #14) > :sfink, this is quite frequent still, we speculated this was related to the > gc::grey work- is there work we can do here? Bug 1335751 slowed down all debug builds, not just Android, so I'm not surprised it bumped a few other things over the time limit. We don't have any evidence that this is more than an overall slowdown, do we? If not, this would be a good candidate for splitting up or lengthening the timeout. Though if it's always on a single test, it may be worth looking at that test to see if it's unreasonably slow (before and/or after the bug 1335751 slowdown.)
Flags: needinfo?(sphink)
:sfink, is there more work to do here? Should we consider disabling this on linux32?
Flags: needinfo?(sphink)
See Also: → 1284733
(In reply to Steve Fink [:sfink] [:s:] from comment #17) > Bug 1335751 slowed down all debug builds, not just Android, so I'm not > surprised it bumped a few other things over the time limit. We don't have > any evidence that this is more than an overall slowdown, do we? If not, this > would be a good candidate for splitting up or lengthening the timeout. > Though if it's always on a single test, it may be worth looking at that test > to see if it's unreasonably slow (before and/or after the bug 1335751 > slowdown.) I think this is more of a hang than a slowdown. Picking a failure log at random... https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=89944549&lineNumber=40304 [task 2017-04-09T20:38:54.740048Z] 20:38:54 INFO - Buffered messages logged at 20:32:21 [task 2017-04-09T20:38:54.742003Z] 20:38:54 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: true: Expected test failure for ({pass:0, method:"GET", hops:[{server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://example.com", allowOrigin:"http://mochi.test:8888", cookie:"a%3D2"}], withCred:"include"}) [task 2017-04-09T20:38:54.743917Z] 20:38:54 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: true: Exception should be TypeError for ({pass:0, method:"GET", hops:[{server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://example.com", allowOrigin:"http://mochi.test:8888", cookie:"a%3D2"}], withCred:"include"}) [task 2017-04-09T20:38:54.747091Z] 20:38:54 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: 1: Expected test to pass for ({pass:1, method:"GET", hops:[{server:"http://mochi.test:8888", noCookie:1}, {server:"http://mochi.test:8888", noCookie:1}, {server:"http://example.com", allowOrigin:"http://mochi.test:8888", noCookie:1}], withCred:"omit"}) [task 2017-04-09T20:38:54.750365Z] 20:38:54 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: 200 === 200: wrong status in test for ({pass:1, method:"GET", hops:[{server:"http://mochi.test:8888", noCookie:1}, {server:"http://mochi.test:8888", noCookie:1}, {server:"http://example.com", allowOrigin:"http://mochi.test:8888", noCookie:1}], withCred:"omit"}) [task 2017-04-09T20:38:54.758536Z] 20:38:54 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: OK === OK: wrong status text for ({pass:1, method:"GET", hops:[{server:"http://mochi.test:8888", noCookie:1}, {server:"http://mochi.test:8888", noCookie:1}, {server:"http://example.com", allowOrigin:"http://mochi.test:8888", noCookie:1}], withCred:"omit"}) [task 2017-04-09T20:38:54.759782Z] 20:38:54 INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | ServiceWorker: <res>hello pass</res> [task 2017-04-09T20:38:54.760195Z] 20:38:54 INFO - === <res>hello pass</res> [task 2017-04-09T20:38:54.762011Z] 20:38:54 INFO - : wrong text in test for ({pass:1, method:"GET", hops:[{server:"http://mochi.test:8888", noCookie:1}, {server:"http://mochi.test:8888", noCookie:1}, {server:"http://example.com", allowOrigin:"http://mochi.test:8888", noCookie:1}], withCred:"omit"}) [task 2017-04-09T20:38:54.762291Z] 20:38:54 INFO - Buffered messages finished [task 2017-04-09T20:38:54.763757Z] 20:38:54 INFO - TEST-UNEXPECTED-TIMEOUT | dom/tests/mochitest/fetch/test_fetch_cors_sw_reroute.html | application timed out after 330 seconds with no output Notice that the test does not progress at all between 20:32:21 and 20:38:54.
Status: NEW → RESOLVED
Closed: 8 years ago
Flags: needinfo?(sphink)
Keywords: intermittent-failure
Resolution: --- → DUPLICATE
Whiteboard: [stockwell needswork] → [stockwell fixed]
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.