Closed Bug 1325942 Opened 3 years ago Closed 3 years ago

Intermittent test_fetch_cors.html,test_fetch_cors_sw_empty_reroute.html,test_fetch_cors_sw_reroute.html | application timed out after 330 seconds with no output

Categories

(Core :: DOM: Service Workers, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla55
Tracking Status
firefox52 --- wontfix
firefox-esr52 --- wontfix
firefox53 --- wontfix
firefox54 --- fixed
firefox55 --- fixed

People

(Reporter: aryx, Assigned: catalinb)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed])

Attachments

(2 files, 1 obsolete file)

https://treeherder.mozilla.org/logviewer.html#?job_id=8436125&repo=autoland

[task 2016-12-27T06:38:49.187949Z] 06:38:48     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: <res>hello pass</res>
[task 2016-12-27T06:38:49.188125Z] 06:38:48     INFO -  === <res>hello pass</res>
[task 2016-12-27T06:38:49.188465Z] 06:38:48     INFO - : wrong text in test for ({pass:1, method:"GET", setCookie:"a=2", withCred:"omit", allowCred:1}) 
[task 2016-12-27T06:38:49.189853Z] 06:38:48     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: 1: Expected test to pass for ({pass:1, method:"GET", cookie:"a=1", withCred:"include", allowCred:1}) 
[task 2016-12-27T06:38:49.191217Z] 06:38:48     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: 200 === 200: wrong status in test for ({pass:1, method:"GET", cookie:"a=1", withCred:"include", allowCred:1}) 
[task 2016-12-27T06:38:49.192633Z] 06:38:48     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: OK === OK: wrong status text for ({pass:1, method:"GET", cookie:"a=1", withCred:"include", allowCred:1}) 
[task 2016-12-27T06:38:49.192973Z] 06:38:48     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: <res>hello pass</res>
[task 2016-12-27T06:38:49.193963Z] 06:38:48     INFO -  === <res>hello pass</res>
[task 2016-12-27T06:38:49.194264Z] 06:38:48     INFO - : wrong text in test for ({pass:1, method:"GET", cookie:"a=1", withCred:"include", allowCred:1}) 
[task 2016-12-27T06:38:49.194439Z] 06:38:48     INFO - Buffered messages finished
[task 2016-12-27T06:38:49.195699Z] 06:38:48     INFO - TEST-UNEXPECTED-TIMEOUT | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | application timed out after 330 seconds with no output
[task 2016-12-27T06:38:49.195935Z] 06:38:48    ERROR - Force-terminating active process(es).
this picked up in frequency, collecting more data here:
https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=linux%20debug%20mochitest-6&tochange=ea193e2bb6590f2776068cd2255d94f505eac8cb&fromchange=1ecb6fcbdb2ad7cff1d4c3749973947d4c113282&selectedJob=82349266

looking at a log:
https://public-artifacts.taskcluster.net/GzUudGiQRMiUcAd77PdWYw/0/public/logs/live_backing.log

I see this data:
[task 2017-03-08T09:35:13.598112Z] 09:35:12     INFO - Buffered messages logged at 09:29:26
[task 2017-03-08T09:35:13.607376Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: 1: Expected test to pass for ({pass:1, 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", allowCred:1, cookie:"a%3D2"}], withCred:"include"}) 
[task 2017-03-08T09:35:13.609774Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: 200 === 200: wrong status in test for ({pass:1, 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", allowCred:1, cookie:"a%3D2"}], withCred:"include"}) 
[task 2017-03-08T09:35:13.612262Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: OK === OK: wrong status text for ({pass:1, 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", allowCred:1, cookie:"a%3D2"}], withCred:"include"}) 
[task 2017-03-08T09:35:13.613918Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: <res>hello pass</res>
[task 2017-03-08T09:35:13.614283Z] 09:35:12     INFO -  === <res>hello pass</res>
[task 2017-03-08T09:35:13.616185Z] 09:35:12     INFO - : wrong text in test for ({pass:1, 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", allowCred:1, cookie:"a%3D2"}], withCred:"include"}) 
[task 2017-03-08T09:35:13.618208Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: 1: Expected test to pass for ({pass:1, method:"GET", hops:[{server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://example.com", allowOrigin:"*", noCookie:1}], withCred:"same-origin"}) 
[task 2017-03-08T09:35:13.620300Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: 200 === 200: wrong status in test for ({pass:1, method:"GET", hops:[{server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://example.com", allowOrigin:"*", noCookie:1}], withCred:"same-origin"}) 
[task 2017-03-08T09:35:13.622297Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: OK === OK: wrong status text for ({pass:1, method:"GET", hops:[{server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://example.com", allowOrigin:"*", noCookie:1}], withCred:"same-origin"}) 
[task 2017-03-08T09:35:13.628003Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: <res>hello pass</res>
[task 2017-03-08T09:35:13.628389Z] 09:35:12     INFO -  === <res>hello pass</res>
[task 2017-03-08T09:35:13.630216Z] 09:35:12     INFO - : wrong text in test for ({pass:1, method:"GET", hops:[{server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://mochi.test:8888", cookie:"a%3D1"}, {server:"http://example.com", allowOrigin:"*", noCookie:1}], withCred:"same-origin"}) 
[task 2017-03-08T09:35:13.630554Z] 09:35:12     INFO - Buffered messages logged at 09:29:27
[task 2017-03-08T09:35:13.633867Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_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:"*", allowCred:1, cookie:"a%3D2"}], withCred:"include"}) 
[task 2017-03-08T09:35:13.636035Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_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:"*", allowCred:1, cookie:"a%3D2"}], withCred:"include"}) 
[task 2017-03-08T09:35:13.640590Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_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-03-08T09:35:13.643023Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_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-03-08T09:35:13.646065Z] 09:35:12     INFO - Buffered messages logged at 09:29:28
[task 2017-03-08T09:35:13.650698Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_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-03-08T09:35:13.652886Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_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-03-08T09:35:13.658321Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_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-03-08T09:35:13.660015Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: <res>hello pass</res>
[task 2017-03-08T09:35:13.660404Z] 09:35:12     INFO -  === <res>hello pass</res>
[task 2017-03-08T09:35:13.666930Z] 09:35:12     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-03-08T09:35:13.667366Z] 09:35:12     INFO - Buffered messages logged at 09:29:30
[task 2017-03-08T09:35:13.670236Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: true: Expected test failure for ({pass:0, method:"POST", body:"hi there", headers:{'Content-Type':"text/plain", 'my-header':"myValue"}, hops:[{server:"http://example.com", allowOrigin:"http://mochi.test:8888"}, {server:"http://sub1.test1.mochi.test:8888", allowOrigin:"http://mochi.test:8888"}]}) 
[task 2017-03-08T09:35:13.672589Z] 09:35:12     INFO - TEST-PASS | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | ServiceWorker: true: Exception should be TypeError for ({pass:0, method:"POST", body:"hi there", headers:{'Content-Type':"text/plain", 'my-header':"myValue"}, hops:[{server:"http://example.com", allowOrigin:"http://mochi.test:8888"}, {server:"http://sub1.test1.mochi.test:8888", allowOrigin:"http://mochi.test:8888"}]}) 
[task 2017-03-08T09:35:13.672916Z] 09:35:12     INFO - Buffered messages finished
[task 2017-03-08T09:35:13.674765Z] 09:35:12     INFO - TEST-UNEXPECTED-TIMEOUT | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | application timed out after 330 seconds with no output
[task 2017-03-08T09:35:13.675105Z] 09:35:12    ERROR - Force-terminating active process(es).
[task 2017-03-08T09:35:13.675452Z] 09:35:12     INFO - Determining child pids from psutil
[task 2017-03-08T09:35:13.675755Z] 09:35:12     INFO - Found child pids: []
[task 2017-03-08T09:35:13.675996Z] 09:35:12     INFO - Killing process: 1975
[task 2017-03-08T09:35:13.676301Z] 09:35:12     INFO - TEST-INFO | started process screentopng
[task 2017-03-08T09:35:14.124502Z] 09:35:14     INFO - TEST-INFO | screentopng: exit 0
[task 2017-03-08T09:35:15.236101Z] 09:35:15     INFO - TEST-INFO | Main app process: exit 6
[task 2017-03-08T09:35:15.236448Z] 09:35:15     INFO - Buffered messages finished
[task 2017-03-08T09:35:15.236897Z] 09:35:15    ERROR - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | application terminated with exit code 6
[task 2017-03-08T09:35:15.237195Z] 09:35:15     INFO - runtests.py | Application ran for: 0:11:16.409938
[task 2017-03-08T09:35:15.237440Z] 09:35:15     INFO - zombiecheck | Reading PID log: /tmp/tmpG0q40zpidlog
[task 2017-03-08T09:35:15.238024Z] 09:35:15     INFO - ==> process 1975 launched child process 1993
[task 2017-03-08T09:35:15.238474Z] 09:35:15     INFO - zombiecheck | Checking for orphan process with PID: 1993
[task 2017-03-08T09:35:15.248014Z] 09:35:15     INFO - mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmpXxwtuU.mozrunner/minidumps/3ddfa980-735f-1e32-3d5b31e1-5d574aea.dmp /home/worker/workspace/build/symbols
[task 2017-03-08T09:35:29.269313Z] 09:35:29     INFO - mozcrash Saved minidump as /home/worker/workspace/build/blobber_upload_dir/3ddfa980-735f-1e32-3d5b31e1-5d574aea.dmp
[task 2017-03-08T09:35:29.273596Z] 09:35:29     INFO - mozcrash Saved app info as /home/worker/workspace/build/blobber_upload_dir/3ddfa980-735f-1e32-3d5b31e1-5d574aea.extra
[task 2017-03-08T09:35:29.604960Z] 09:35:29     INFO - PROCESS-CRASH | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | application crashed [@ linux-gate.so + 0x440]
[task 2017-03-08T09:35:29.607765Z] 09:35:29     INFO - Crash dump filename: /tmp/tmpXxwtuU.mozrunner/minidumps/3ddfa980-735f-1e32-3d5b31e1-5d574aea.dmp
[task 2017-03-08T09:35:29.609595Z] 09:35:29     INFO - Operating system: Linux
[task 2017-03-08T09:35:29.611527Z] 09:35:29     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-08T09:35:29.613328Z] 09:35:29     INFO - CPU: x86
[task 2017-03-08T09:35:29.615134Z] 09:35:29     INFO -      GenuineIntel family 6 model 62 stepping 4
[task 2017-03-08T09:35:29.616907Z] 09:35:29     INFO -      1 CPU
[task 2017-03-08T09:35:29.618678Z] 09:35:29     INFO - 
[task 2017-03-08T09:35:29.620403Z] 09:35:29     INFO - GPU: UNKNOWN
[task 2017-03-08T09:35:29.622117Z] 09:35:29     INFO - 
[task 2017-03-08T09:35:29.624042Z] 09:35:29     INFO - Crash reason:  SIGABRT
[task 2017-03-08T09:35:29.626068Z] 09:35:29     INFO - Crash address: 0x4c3
[task 2017-03-08T09:35:29.627895Z] 09:35:29     INFO - Process uptime: not available
[task 2017-03-08T09:35:29.629648Z] 09:35:29     INFO - 
[task 2017-03-08T09:35:29.631358Z] 09:35:29     INFO - Thread 0 (crashed)
[task 2017-03-08T09:35:29.633096Z] 09:35:29     INFO -  0  linux-gate.so + 0x440
[task 2017-03-08T09:35:29.634941Z] 09:35:29     INFO -     eip = 0xf7769440   esp = 0xffca0a60   ebp = 0xffca0ad8   ebx = 0xe05379a0
[task 2017-03-08T09:35:29.636901Z] 09:35:29     INFO -     esi = 0x00000000   edi = 0xf75cdff4   eax = 0xfffffffc   ecx = 0x00000005
[task 2017-03-08T09:35:29.638724Z] 09:35:29     INFO -     edx = 0xffffffff   efl = 0x00000246
[task 2017-03-08T09:35:29.640572Z] 09:35:29     INFO -     Found by: given as instruction pointer in context
[task 2017-03-08T09:35:29.642532Z] 09:35:29     INFO -  1  libglib-2.0.so.0.3200.4 + 0x4706e
[task 2017-03-08T09:35:29.644388Z] 09:35:29     INFO -     eip = 0xf651006e   esp = 0xffca0ae0   ebp = 0xe05379a0
[task 2017-03-08T09:35:29.646184Z] 09:35:29     INFO -     Found by: previous frame's frame pointer
[task 2017-03-08T09:35:29.647940Z] 09:35:29     INFO -  2  libglib-2.0.so.0.3200.4 + 0xf8900
[task 2017-03-08T09:35:29.655132Z] 09:35:29     INFO -     eip = 0xf65c1900   esp = 0xffca0af8   ebp = 0xe05379a0
[task 2017-03-08T09:35:29.657086Z] 09:35:29     INFO -     Found by: stack scanning
[task 2017-03-08T09:35:29.658892Z] 09:35:29     INFO -  3  libglib-2.0.so.0.3200.4 + 0x86430
[task 2017-03-08T09:35:29.660733Z] 09:35:29     INFO -     eip = 0xf654f430   esp = 0xffca0b00   ebp = 0xe05379a0
[task 2017-03-08T09:35:29.662466Z] 09:35:29     INFO -     Found by: stack scanning
[task 2017-03-08T09:35:29.664286Z] 09:35:29     INFO -  4  libglib-2.0.so.0.3200.4 + 0x86956
[task 2017-03-08T09:35:29.667354Z] 09:35:29     INFO -     eip = 0xf654f956   esp = 0xffca0b08   ebp = 0xe05379a0
[task 2017-03-08T09:35:29.669128Z] 09:35:29     INFO -     Found by: stack scanning
[task 2017-03-08T09:35:29.671020Z] 09:35:29     INFO -  5  libxul.so!nsFilePicker::Done(_GtkWidget*, int)::{lambda(void*)#1}::_FUN(void*) + 0x21
[task 2017-03-08T09:35:29.672839Z] 09:35:29     INFO -     eip = 0xf2fbae1f   esp = 0xffca0b10   ebp = 0xe05379a0
[task 2017-03-08T09:35:29.675034Z] 09:35:29     INFO -     Found by: stack scanning
[task 2017-03-08T09:35:29.677080Z] 09:35:29     INFO -  6  libglib-2.0.so.0.3200.4 + 0xf8594
[task 2017-03-08T09:35:29.680387Z] 09:35:29     INFO -     eip = 0xf65c1594   esp = 0xffca0b14   ebp = 0xe05379a0
[task 2017-03-08T09:35:29.682155Z] 09:35:29     INFO -     Found by: stack scanning
[task 2017-03-08T09:35:29.683920Z] 09:35:29     INFO -  7  libglib-2.0.so.0.3200.4 + 0x46efb
[task 2017-03-08T09:35:29.685857Z] 09:35:29     INFO -     eip = 0xf650fefb   esp = 0xffca0b2c   ebp = 0xffca0b58
[task 2017-03-08T09:35:29.689655Z] 09:35:29     INFO -     Found by: stack scanning
[task 2017-03-08T09:35:29.691738Z] 09:35:29     INFO -  8  libxul.so!nsAppShell::ProcessNextNativeEvent [nsAppShell.cpp:ea193e2bb659 : 270 + 0xc]
[task 2017-03-08T09:35:29.693689Z] 09:35:29     INFO -     eip = 0xf2fbaeb6   esp = 0xffca0b60   ebp = 0x00000000
[task 2017-03-08T09:35:29.695486Z] 09:35:29     INFO -     Found by: previous frame's frame pointer


we force a crash on timeout, so that is where we were at, could be random.


as a note, this test typically takes 2+ minutes to run:
[task 2017-03-08T07:02:29.484378Z] 07:02:29     INFO - TEST-OK | dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | took 127472ms

ni myself to follow up after retriggers
Flags: needinfo?(jmaher)
Whiteboard: [stockwell needswork]
many retriggers later:
https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=linux%20debug%20mochitest-6&tochange=ea193e2bb6590f2776068cd2255d94f505eac8cb&fromchange=e1a8167f17dd9c795e5846de5e24d6ce0cc4e0d9&selectedJob=84047478

not quite sure, :gbrown, maybe you could interpret this to a root cause, needs more retriggers, or just look at the test caes?
Flags: needinfo?(jmaher) → needinfo?(gbrown)
I wonder if maybe this is a case of bug 1335751 changing the timing slightly.

More than 90% of failures are on linux32/debug; we might consider skipping on that platform.

Will look into it a bit...
(In reply to Joel Maher ( :jmaher) from comment #5)
> many retriggers later:
> https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-
> searchStr=linux%20debug%20mochitest-
> 6&tochange=ea193e2bb6590f2776068cd2255d94f505eac8cb&fromchange=e1a8167f17dd9c
> 795e5846de5e24d6ce0cc4e0d9&selectedJob=84047478
> 
> not quite sure, :gbrown, maybe you could interpret this to a root cause,
> needs more retriggers, or just look at the test caes?

I don't see anything suspicious in that range and I note that the test was failing infrequently for a couple months prior to that range -- I'm not sure we can conclude anything from the frequency change.

I don't see any recent changes to the test or its obvious dependencies.


It's been a while, but I see Ehsan did a lot of work on these tests; I wonder if he might be interested?
Flags: needinfo?(gbrown) → needinfo?(ehsan)
Catalin, do you have time to take a look at this by any chance?  Thanks!
Flags: needinfo?(ehsan) → needinfo?(catalin.badea392)
I think our 30 sec grace period after each event is broken and we terminate the worker, which causes some fetch responses to be dropped.
Assignee: nobody → catalin.badea392
Flags: needinfo?(catalin.badea392)
Hmm.  I thought we explicitly tested that stuff in Kit's test here:

https://dxr.mozilla.org/mozilla-central/source/dom/push/test/test_serviceworker_lifetime.html

Can you check to see if that is working right?
Comment on attachment 8852383 [details] [diff] [review]
Fix test_fetch_cors_sw_empty_reroute.html.

Review of attachment 8852383 [details] [diff] [review]:
-----------------------------------------------------------------

Ugh, so sorry about this.  :-(  I never learned how to use this API properly...
Attachment #8852383 - Flags: review?(ehsan) → review+
https://hg.mozilla.org/mozilla-central/rev/167d391cabb9
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Duplicate of this bug: 1284755
See Also: → 1282207
Whiteboard: [stockwell needswork] → [stockwell fixed]
Bah, I had to back this out from Aurora/Beta for ASAN leaks. But for whatever reason, m-c is fine :\
https://treeherder.mozilla.org/logviewer.html#?job_id=87631448&repo=mozilla-aurora

Also, there's a lot of "*** error running SJS at /home/worker/workspace/build/tests/mochitest/tests/dom/security/test/cors/file_CrossSiteXHR_server.sjs: 2147746065 on line NaN" spew in the logs for this test. Is that expected?

https://hg.mozilla.org/releases/mozilla-aurora/rev/05822f3a0657
https://hg.mozilla.org/releases/mozilla-beta/rev/fe3e3c0ea489
Flags: needinfo?(catalin.badea392)
(In reply to Ryan VanderMeulen [:RyanVM] from comment #21)
> Bah, I had to back this out from Aurora/Beta for ASAN leaks. But for
> whatever reason, m-c is fine :\
> https://treeherder.mozilla.org/logviewer.html#?job_id=87631448&repo=mozilla-
> aurora
> 
> Also, there's a lot of "*** error running SJS at
> /home/worker/workspace/build/tests/mochitest/tests/dom/security/test/cors/
> file_CrossSiteXHR_server.sjs: 2147746065 on line NaN" spew in the logs for
> this test. Is that expected?
> 
> https://hg.mozilla.org/releases/mozilla-aurora/rev/05822f3a0657
> https://hg.mozilla.org/releases/mozilla-beta/rev/fe3e3c0ea489

I noticed that, too. I tried debugging it for a bit, but got some weird results, with the error stopping from occurring as I added debugging statements.

ehsan, are these sjs errors expected?
Flags: needinfo?(catalin.badea392) → needinfo?(ehsan)
Looks like the problem still persists.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
this has reduced in frequency a bit, still on the high side.  The pattern looks to be the same.
Whiteboard: [stockwell fixed] → [stockwell needswork]
Depends on: 1353893
(In reply to Ryan VanderMeulen [:RyanVM] from comment #21)
> Bah, I had to back this out from Aurora/Beta for ASAN leaks. But for
> whatever reason, m-c is fine :\

I figured out why m-c was fine...
The patch in this bug needs to be backed out from m-c for causing an LSan leak. Better sooner than later, so we can reenable LSan checking.
Keywords: checkin-needed
Target Milestone: mozilla55 → ---
(In reply to Andrew McCreight [:mccr8] from comment #26)
> I figured out why m-c was fine...

Hah, indeed!

https://hg.mozilla.org/integration/autoland/rev/aeb4a39fd9e8388dbcea4b6aca434edad3405d89
Keywords: checkin-needed
This test seems to be broken on 3 different levels:
1. the incorrect use of SW api (which was fixed by the backed out patch)
2. whatever is still causing the timeouts
3. memory leaks?

There was nothing wrong with the changes in the patch and backing it out doesn't help surface these issues. Why not just flag the failure on tree herder?
Flags: needinfo?(ryanvm)
The leaks from comment 21 were happening on m-c as well (permanently, not intermittently). Unfortunately, LSAN leak checking was broken due to bug 1353858, so it went unnoticed at the time. In order to land the fix for LSAN, we had to back this out so the leaks wouldn't leave the suite permafailing afterwards. Sorry if that wasn't made clear enough in the prior comments, hopefully that better clarifies why the backout happened. Feel free to ping me or mccr8 on IRC if you have more questions.

This also makes me wonder even more now if those SJS warnings are indeed related to the leaks, now that we know that the lack of test failures on m-c was due to the test harness being broken.
Flags: needinfo?(ryanvm)
this started failing on April 7th on linux32 debug, should we assume that is a new issue?
Flags: needinfo?(catalin.badea392)
See Also: → 1284733
Summary: Intermittent dom/tests/mochitest/fetch/test_fetch_cors_sw_empty_reroute.html | application timed out after 330 seconds with no output → Intermittent test_fetch_cors.html,test_fetch_cors_sw_empty_reroute.html,test_fetch_cors_sw_reroute.html | application timed out after 330 seconds with no output
Duplicate of this bug: 1284733
Duplicate of this bug: 1282207
(In reply to Joel Maher ( :jmaher) from comment #33)
> this started failing on April 7th on linux32 debug, should we assume that is
> a new issue?

No, that's expected due to the backout in comment 29. Yes, we need a revised patch that doesn't permaleak, though.
after chatting on irc with :RyanVM, he assures me this isn't an issue with the cors tests, but all of the fetch tests and we just happen to be timing out in the cors tests.

In the last 2 days we have 167 failures of all the _cors* bugs- My plan was to disable the 3 tests, but it sounds like I need to disable the entire directory as some other test XXX seconds into the browser session will hit this error.

:catalin- is there a better option than disabling the entire directory?
I wanted to have a patch ready- I will land this on Monday assuming I hear no other reason for not doing this and there is a valid plan in the short term to fix this!
Attachment #8858096 - Flags: review?(gbrown)
Attachment #8858096 - Flags: review?(gbrown) → review+
Another possibility would be relanding Catalin's patch and just disabling test_formdataparsing.html and test_formdataparsing_sw_reroute.html, which were causing the LSan leaks.
and we would only disable them on lsan (or asan) builds?  that seems like a better solution- happy to do that and/or other suggestions.
Duplicate of this bug: 1356360
can someone point me to the patch to land and the tests to disable and I will push to try- I have not been able to figure that out by reading this bug.
(In reply to Joel Maher ( :jmaher) from comment #46)
> can someone point me to the patch to land and the tests to disable and I
> will push to try- I have not been able to figure that out by reading this
> bug.

The patch is https://hg.mozilla.org/mozilla-central/rev/167d391cabb9
The tests are test_formdataparsing.html and test_formdataparsing_sw_reroute.html in dom/tests/mochitest/fetch/. As you said, they can probably just be disabled on ASan builds.
Attachment #8858378 - Flags: review?(ryanvm) → review+
Pushed by jmaher@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/6a14de14c0f4
Fix test_fetch_cors_sw_empty_reroute.html. r=ehsan
https://hg.mozilla.org/integration/mozilla-inbound/rev/caca2a2510f5
disable two tests in asan for leaks. r=RyanVM
so 2 tests are disabled for asan:
dom/tests/mochitest/fetch/test_formdataparsing.html
dom/tests/mochitest/fetch/test_formdataparsing_sw_reroute.html

I would like to leave this bug open, but happy to file a new one to track fixing those tests.  There are already 2 ni? on this bug, so assuming those will coordinate on the right thing to do.
Keywords: leave-open
Whiteboard: [stockwell needswork] → [stockwell fixed]
I think we should spin off a new bug for the remaining work at this point, but that's complicated by the manifest annotations pointing to *this* bug :(
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Flags: needinfo?(ehsan)
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
See Also: → 1359565
(In reply to Ryan VanderMeulen [:RyanVM] from comment #55)
> I think we should spin off a new bug for the remaining work at this point,
> but that's complicated by the manifest annotations pointing to *this* bug :(

Filed bug 1359565.
Flags: needinfo?(catalin.badea392)
You need to log in before you can comment on or make changes to this bug.