1340037 - 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()

Status: RESOLVED FIXED

(Core :: Audio/Video: Playback, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: philringnalda [at] gmail.com

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

https://queue.taskcluster.net/v1/task/bIxtFdReSfKkt5d-_if76Q/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Intermittent Failures Robot]

8 failures in 833 pushes (0.01 failures/push) were associated with this bug in the last 7 days.  
Repository breakdown:
* autoland: 4
* mozilla-inbound: 2
* mozilla-central: 1
* graphics: 1

Platform breakdown:
* linux64: 6
* linux32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340037&startday=2017-02-13&endday=2017-02-19&tree=all

Comment 2

[Intermittent Failures Robot]

9 failures in 812 pushes (0.011 failures/push) were associated with this bug in the last 7 days.  
Repository breakdown:
* autoland: 6
* try: 2
* mozilla-central: 1

Platform breakdown:
* linux64: 8
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340037&startday=2017-02-20&endday=2017-02-26&tree=all

Comment 3

[Intermittent Failures Robot]

6 failures in 790 pushes (0.008 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 3
* autoland: 2
* graphics: 1

Platform breakdown:
* linux64: 5
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340037&startday=2017-03-06&endday=2017-03-12&tree=all

Comment 4

[Intermittent Failures Robot]

29 failures in 777 pushes (0.037 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 15
* mozilla-inbound: 8
* oak: 2
* mozilla-aurora: 2
* try: 1
* graphics: 1

Platform breakdown:
* linux64: 24
* linux32: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340037&startday=2017-03-13&endday=2017-03-19&tree=all

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

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"

Comment 6

[Intermittent Failures Robot]

17 failures in 898 pushes (0.019 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 9
* mozilla-inbound: 3
* mozilla-aurora: 2
* try: 1
* mozilla-central: 1
* graphics: 1

Platform breakdown:
* linux64: 15
* linux32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340037&startday=2017-03-20&endday=2017-03-26&tree=all

Comment 7

[Intermittent Failures Robot]

28 failures in 845 pushes (0.033 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 12
* mozilla-inbound: 10
* mozilla-central: 3
* try: 1
* mozilla-aurora: 1
* graphics: 1

Platform breakdown:
* linux64: 24
* linux32: 4

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340037&startday=2017-03-27&endday=2017-04-02&tree=all

Comment 8

[Intermittent Failures Robot]

25 failures in 867 pushes (0.029 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 10
* mozilla-inbound: 5
* mozilla-central: 4
* mozilla-aurora: 3
* graphics: 2
* oak: 1

Platform breakdown:
* linux64: 20
* linux32: 4
* linux64-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340037&startday=2017-04-03&endday=2017-04-09&tree=all

Comment 9

[Intermittent Failures Robot]

40 failures in 894 pushes (0.045 failures/push) were associated with this bug in the last 7 days. 

This is the #36 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* autoland: 14
* try: 10
* mozilla-inbound: 7
* mozilla-aurora: 4
* oak: 2
* mozilla-central: 2
* graphics: 1

Platform breakdown:
* linux64: 29
* linux32: 8
* linux64-qr: 2
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340037&startday=2017-04-10&endday=2017-04-16&tree=all

Comment 10

[Joel Maher ( :jmaher ) (UTC -8)]

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)?

Comment 11

[JW Wang [:jwwang] [:jw_wang]]

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.

Comment 12

[JW Wang [:jwwang] [:jw_wang]]

Attachment: 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()".

Note this patch doesn't fix the crash in comment 10 which seems to be related to ChromiumCDMParent.

Review commit: https://reviewboard.mozilla.org/r/131452/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/131452/

Comment 13

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

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

Comment 14

[JW Wang [:jwwang] [:jw_wang]]

Thanks!

Comment 15

[Pulsebot]

Pushed by [e-mail]:
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

Comment 16

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/227ea3770852

Comment 17

[Intermittent Failures Robot]

17 failures in 817 pushes (0.021 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 7
* try: 4
* mozilla-central: 2
* graphics: 2
* mozilla-inbound: 1
* mozilla-aurora: 1

Platform breakdown:
* linux64: 13
* linux32: 3
* linux64-qr: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340037&startday=2017-04-17&endday=2017-04-23&tree=all

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/ec47fae0f90f