Intermittent dom/media/test/test_eme_canvas_blocked.html | [02:35:55.133] WebM vorbis audio & vp9 video clearkey with subsample encryption-22 key session type should match - Result logged after SimpleTest.finish()

RESOLVED FIXED in Firefox 54

Status

()

defect
P5
normal
RESOLVED FIXED
2 years ago
2 years ago

People

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

Tracking

({intermittent-failure})

unspecified
mozilla55
Points:
---
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox54 fixed, firefox55 fixed)

Details

(Whiteboard: [stockwell fixed])

Attachments

(1 attachment)

Component: Audio/Video → Audio/Video: Playback
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"
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)?
Flags: needinfo?(jwwang)
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.
Flags: needinfo?(jwwang)
Attachment #8859426 - Flags: review?(gsquelart)
Assignee: nobody → jwwang
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+
Thanks!
Pushed by jwwang@mozilla.com:
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
https://hg.mozilla.org/mozilla-central/rev/227ea3770852
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Whiteboard: [stockwell needswork] → [stockwell fixed]
You need to log in before you can comment on or make changes to this bug.