Bug 1340037 - per comment 11, we need to wait for all initData are processed before finishing the test to avoid "Result logged after SimpleTest.finish()".
59 bytes, text/x-review-board-request
this is increasing in frequency- it is misleading as this is primarily linux64-pgo, as that is the case we only run this 1 out of 5 pushes on autoland/inbound, that increases the failure rate significantly for linux64. Good news is that in the last 2 days there have been 1 instance, so I will assume this "self corrected"
2 years ago
Priority: -- → P5
40 failures in the last week, I would like to start getting traction on this bug as this has been consistent for many weeks and finally increased over our threshold of 30 failures/week. looking at a failure in this log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=91929751&lineNumber=2466 I see this in the log: [task 2017-04-16T00:16:50.843209Z] 00:16:50 INFO - TEST-START | dom/media/test/test_eme_canvas_blocked.html [task 2017-04-16T00:16:51.090955Z] 00:16:51 INFO - file=[xpconnect wrapped nsILocalFile] [task 2017-04-16T00:16:51.140051Z] 00:16:51 INFO - file=[xpconnect wrapped nsILocalFile] [task 2017-04-16T00:16:51.208298Z] 00:16:51 INFO - file=[xpconnect wrapped nsILocalFile] [task 2017-04-16T00:16:51.223944Z] 00:16:51 INFO - file=[xpconnect wrapped nsILocalFile] [task 2017-04-16T00:16:51.264389Z] 00:16:51 INFO - file=[xpconnect wrapped nsILocalFile] [task 2017-04-16T00:16:51.284485Z] 00:16:51 INFO - file=[xpconnect wrapped nsILocalFile] [task 2017-04-16T00:16:52.957975Z] 00:16:52 INFO - GECKO(1703) | MEMORY STAT | vsize 2189MB | residentFast 243MB | heapAllocated 110MB [task 2017-04-16T00:16:52.973172Z] 00:16:52 INFO - TEST-OK | dom/media/test/test_eme_canvas_blocked.html | took 2129ms [task 2017-04-16T00:16:52.978348Z] 00:16:52 INFO - TEST-INFO | started process screentopng [task 2017-04-16T00:16:53.355584Z] 00:16:53 INFO - TEST-INFO | screentopng: exit 0 [task 2017-04-16T00:16:53.356330Z] 00:16:53 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_canvas_blocked.html | [00:16:52.960] WebM vorbis audio & vp9 video clearkey with subsample encryption-22 key session type should match - Result logged after SimpleTest.finish() [task 2017-04-16T00:16:53.357113Z] 00:16:53 INFO - Not taking screenshot here: see the one that was previously logged [task 2017-04-16T00:16:53.358232Z] 00:16:53 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_canvas_blocked.html | [00:16:52.960] WebM vorbis audio & vp9 video clearkey with subsample encryption-22 message event should contain key ID array - Result logged after SimpleTest.finish() [task 2017-04-16T00:16:53.359024Z] 00:16:53 INFO - TEST-START | dom/media/test/test_eme_detach_media_keys.html [task 2017-04-16T00:16:53.359979Z] 00:16:53 INFO - GECKO(1703) | ExceptionHandler::GenerateDump cloned child 2448 [task 2017-04-16T00:16:53.360624Z] 00:16:53 INFO - GECKO(1703) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child [task 2017-04-16T00:16:53.361444Z] 00:16:53 INFO - GECKO(1703) | ExceptionHandler::WaitForContinueSignal waiting for continue signal... [task 2017-04-16T00:16:53.361844Z] 00:16:53 INFO - GECKO(1703) | [GMP 2442] WARNING: pipe error (3): Connection reset by peer: file /home/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353 [task 2017-04-16T00:16:53.388151Z] 00:16:53 INFO - TEST-INFO | Main app process: exit 11 [task 2017-04-16T00:16:53.388729Z] 00:16:53 INFO - Buffered messages finished [task 2017-04-16T00:16:53.389411Z] 00:16:53 ERROR - TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_detach_media_keys.html | application terminated with exit code 11 [task 2017-04-16T00:16:53.391005Z] 00:16:53 INFO - runtests.py | Application ran for: 0:02:23.844747 [task 2017-04-16T00:16:53.391968Z] 00:16:53 INFO - zombiecheck | Reading PID log: /tmp/tmpbyT3czpidlog [task 2017-04-16T00:16:53.392969Z] 00:16:53 INFO - ==> process 1703 launched child process 1730 [task 2017-04-16T00:16:53.393885Z] 00:16:53 INFO - ==> process 1703 launched child process 2442 [task 2017-04-16T00:16:53.394703Z] 00:16:53 INFO - zombiecheck | Checking for orphan process with PID: 1730 [task 2017-04-16T00:16:53.395586Z] 00:16:53 INFO - zombiecheck | Checking for orphan process with PID: 2442 [task 2017-04-16T00:16:53.396442Z] 00:16:53 INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/fP0lA5rFQRKJ34-mXJo0kw/artifacts/public/build/target.crashreporter-symbols.zip [task 2017-04-16T00:16:57.598261Z] 00:16:57 INFO - mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmpReFKfW.mozrunner/minidumps/7291bd74-bdb5-4b7b-9998-ff45499b363b.dmp /tmp/tmpE9MjCW [task 2017-04-16T00:17:03.495580Z] 00:17:03 INFO - mozcrash Saved minidump as /home/worker/workspace/build/blobber_upload_dir/7291bd74-bdb5-4b7b-9998-ff45499b363b.dmp [task 2017-04-16T00:17:03.496608Z] 00:17:03 INFO - mozcrash Saved app info as /home/worker/workspace/build/blobber_upload_dir/7291bd74-bdb5-4b7b-9998-ff45499b363b.extra [task 2017-04-16T00:17:03.871027Z] 00:17:03 INFO - PROCESS-CRASH | dom/media/test/test_eme_detach_media_keys.html | application crashed [@ mozilla::gmp::ChromiumCDMParent::RecvOnSessionKeysChange] [task 2017-04-16T00:17:03.871467Z] 00:17:03 INFO - Crash dump filename: /tmp/tmpReFKfW.mozrunner/minidumps/7291bd74-bdb5-4b7b-9998-ff45499b363b.dmp [task 2017-04-16T00:17:03.871827Z] 00:17:03 INFO - Operating system: Linux [task 2017-04-16T00:17:03.872200Z] 00:17:03 INFO - 0.0.0 Linux 3.13.0-112-generic #159-Ubuntu SMP Fri Mar 3 15:26:07 UTC 2017 x86_64 [task 2017-04-16T00:17:03.872624Z] 00:17:03 INFO - CPU: amd64 [task 2017-04-16T00:17:03.872991Z] 00:17:03 INFO - family 6 model 62 stepping 4 [task 2017-04-16T00:17:03.873377Z] 00:17:03 INFO - 2 CPUs [task 2017-04-16T00:17:03.873727Z] 00:17:03 INFO - [task 2017-04-16T00:17:03.874087Z] 00:17:03 INFO - GPU: UNKNOWN [task 2017-04-16T00:17:03.874441Z] 00:17:03 INFO - [task 2017-04-16T00:17:03.874867Z] 00:17:03 INFO - Crash reason: SIGSEGV [task 2017-04-16T00:17:03.875240Z] 00:17:03 INFO - Crash address: 0x0 [task 2017-04-16T00:17:03.875644Z] 00:17:03 INFO - Process uptime: not available [task 2017-04-16T00:17:03.876008Z] 00:17:03 INFO - [task 2017-04-16T00:17:03.876408Z] 00:17:03 INFO - Thread 17 (crashed) [task 2017-04-16T00:17:03.876805Z] 00:17:03 INFO - 0 libxul.so!mozilla::gmp::ChromiumCDMParent::RecvOnSessionKeysChange [ChromiumCDMParent.cpp:938824ac5749 : 464 + 0x0] [task 2017-04-16T00:17:03.877251Z] 00:17:03 INFO - rax = 0x0000000000000000 rdx = 0x00007fd7a9afdaa0 [task 2017-04-16T00:17:03.877629Z] 00:17:03 INFO - rcx = 0x00007fd7aa695fe0 rbx = 0x00007fd79d9bc690 [task 2017-04-16T00:17:03.878010Z] 00:17:03 INFO - rsi = 0x00007fd7a9afdab0 rdi = 0x00007fd7a8795c00 [task 2017-04-16T00:17:03.878429Z] 00:17:03 INFO - rbp = 0x00007fd7a9afda50 rsp = 0x00007fd7a9afd940 [task 2017-04-16T00:17:03.878850Z] 00:17:03 INFO - r8 = 0x0000000000000042 r9 = 0x0000000000000000 [task 2017-04-16T00:17:03.879258Z] 00:17:03 INFO - r10 = 0x00007fd7aced5790 r11 = 0x00007fd78f9898e8 [task 2017-04-16T00:17:03.879636Z] 00:17:03 INFO - r12 = 0xe5e5e5e5e5e5e5e5 r13 = 0x00007fd7a9afd970 [task 2017-04-16T00:17:03.880047Z] 00:17:03 INFO - r14 = 0x00007fd7a9afd980 r15 = 0x00007fd7a9afdaa0 [task 2017-04-16T00:17:03.880454Z] 00:17:03 INFO - rip = 0x00007fd7b992d434 [task 2017-04-16T00:17:03.880830Z] 00:17:03 INFO - Found by: given as instruction pointer in context [task 2017-04-16T00:17:03.881272Z] 00:17:03 INFO - 1 libxul.so!mozilla::gmp::PChromiumCDMParent::OnMessageReceived [PChromiumCDMParent.cpp:938824ac5749 : 653 + 0x18] [task 2017-04-16T00:17:03.881646Z] 00:17:03 INFO - rbx = 0x00007fd79d9bc690 rbp = 0x00007fd7a9afdb60 ... this is currently run on all configurations except on android: https://dxr.mozilla.org/mozilla-central/source/dom/media/test/mochitest.ini#728 as this fails often in pgo, our overall failure rate is much higher since pgo is run once/5 pushes; so for linux64 that would be more like 100 failures if we ran this everytime. :jwwang, I see that you edited this test case recently, could you find some time to look into fixing this (or redirect to someone who could do it)?
Whiteboard: [stockwell needswork]
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=91836485&lineNumber=2500 TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_canvas_blocked.html | [03:30:40.25] WebM vorbis audio & vp9 video clearkey with subsample encryption-22 key session type should match - Result logged after SimpleTest.finish() The message is printed by http://searchfox.org/mozilla-central/rev/4bd7a206dea5382c97a8a0c30beef668cc449f5b/dom/media/test/eme.js#116. It looks like there is a race between the 'loadeddata' event at http://searchfox.org/mozilla-central/rev/214345204f1e7d97abb571b7992b6deedb5ff98f/dom/media/test/test_eme_canvas_blocked.html#25 and the 'message' event at http://searchfox.org/mozilla-central/rev/4bd7a206dea5382c97a8a0c30beef668cc449f5b/dom/media/test/eme.js#357. I think we should wait for all initData are processed before finishing the test to avoid such races. Patches are coming up.
Attachment #8859426 - Flags: review?(gsquelart)
Comment on attachment 8859426 [details] Bug 1340037 - per comment 11, we need to wait for all initData are processed before finishing the test to avoid "Result logged after SimpleTest.finish()". https://reviewboard.mozilla.org/r/131452/#review134150
Attachment #8859426 - Flags: review?(gsquelart) → review+
Pushed by firstname.lastname@example.org: https://hg.mozilla.org/integration/autoland/rev/227ea3770852 per comment 11, we need to wait for all initData are processed before finishing the test to avoid "Result logged after SimpleTest.finish()". r=gerald
Whiteboard: [stockwell needswork] → [stockwell fixed]
You need to log in before you can comment on or make changes to this bug.