Open Bug 1186406 Opened 9 years ago Updated 2 years ago

Intermittent test_eme_playback.html | 400x225 then 640x360-17 got error event; [object Event]

Categories

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

Product:
Core
Component:
Audio/Video: Playback
Type:
defect

Tracking

()

Tracking Flags:
Tracking Status
firefox41 --- unaffected
firefox42 --- disabled
firefox43 --- disabled
firefox-esr38 --- unaffected

People

(Reporter: cbook, Unassigned)

References

(
URL
)

Details

(Keywords: intermittent-failure, Whiteboard: [test disabled on Windows][leave open])

Attachments

(2 files)

MozReview Request: Bug 1186406 - Log why GMPVideoDecoderParent::Decode() fails. r?gerald
40 bytes, text/x-review-board-request
mozbugz
: review+
Details
MozReview Request: Bug 1186406 - Copy input to ClearKey's decoder, so we can return its containing shmem earlier. r?gerald
40 bytes, text/x-review-board-request
mozbugz
: review+
Details 
https://treeherder.mozilla.org/logviewer.html#?job_id=12001887&repo=mozilla-inbound

06:31:01 INFO - 2339 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_playback.html | 400x225 then 640x360-17 got error event; [object Event]
Flags: needinfo?(gsquelart)
Guessing an MSE issue, may be related to bug 1186556.
Flags: needinfo?(gsquelart) → needinfo?(jyavenard)
ni? myself to disable this tomorrow
Flags: needinfo?(ryanvm)
status-firefox41: --- → unaffected
status-firefox42: --- → disabled
status-firefox43: --- → disabled
status-firefox-esr38: --- → unaffected
Flags: needinfo?(ryanvm)
Flags: needinfo?(jyavenard)
Whiteboard: [test disabled on Windows][leave open]
Component: Audio/Video → Audio/Video: Playback
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #256)
> ni? myself to disable this tomorrow

I'd have appreciated it if you ni? me, or a module peer, rather than disabling our tests and leaving us flying blind without knowing about it.
Priority: -- → P2
Assignee: nobody → cpearce
Bug 1186406 - Log why GMPVideoDecoderParent::Decode() fails. r?gerald

This helps us to identify the cause of such failures.
Attachment #8693437 - Flags: review?(gsquelart)
Bug 1186406 - Copy input to ClearKey's decoder, so we can return its containing shmem earlier. r?gerald

We're failing in the "Very rough kill-switch" case in
GMPVideoDecoderParent::Decode() we find that too many shmems are in use when we
come to send a "Decode" message to the GMP, and that causes an error which
percolates up to cause the test failure.

This patch changes gmp-clearkey to copy the input encrypted and compressed
sample and immediately return the shmem to the parent process. We are
copying the data anyway when we decrypt, so we can rejigg things so that we
don't actually end up doing a second copy.
Attachment #8693438 - Flags: review?(gsquelart)
Also note, with the above fix, I'm still seeing a crash, but this time a lot less frequently.

Mochitest log:

Test File Name:	Test:	Error message:
/tests/dom/media/test/test_eme_playback.html	undefined	
/tests/dom/media/test/test_eme_playback.html	undefined	
/tests/dom/media/test/test_eme_playback.html	undefined	
/tests/dom/media/test/test_eme_playback.html	undefined	
/tests/dom/media/test/test_eme_playback.html	640x480@959kbps with 1st keys then 640x480@624kbps with 2nd keys-11: session[].generateRequest(cenc, 0000003470737368010000001077efecc0b24d02ace33c1e52e2fb4b000000017e571d037e571d037e571d037e571d1200000000) failed; InvalidStateError: Promise still outstanding at MediaKeys shutdown	
/tests/dom/media/test/test_eme_playback.html	640x480@959kbps with 1st keys then 640x480@624kbps with 2nd keys-11 got error event; [object Event]	
/tests/dom/media/test/test_eme_playback.html	400x300 with 1st keys then 640x480 with 2nd keys-10 got error event; [object Event]	
/tests/dom/media/test/test_eme_playback.html	undefined


Main thread callstack in the GMP process:

plugin-container.exe!memcpy(unsigned char * dst, unsigned char * src, unsigned long count) Line 188	Unknown
kernel32.dll!_MapPredefinedHandleInternal@16()	Unknown
kernel32.dll!_RegOpenKeyExInternalW@24()	Unknown
kernel32.dll!_RegOpenKeyExW@20()	Unknown
msmpeg2vdec.dll!52f246bc()	Unknown
[Frames below may be incorrect and/or missing, no symbols loaded for msmpeg2vdec.dll]	
[External Code]	
clearkey.dll!wmf::WMFH264Decoder::SendMFTMessage(_MFT_MESSAGE_TYPE aMsg, unsigned int aData) Line 190	C++
clearkey.dll!wmf::WMFH264Decoder::Init(int aCoreCount) Line 64	C++
clearkey.dll!VideoDecoder::InitDecode(const GMPVideoCodec & aCodecSettings, const unsigned char * aCodecSpecific, unsigned int aCodecSpecificLength, GMPVideoDecoderCallback * aCallback, int aCoreCount) Line 61	C++
xul.dll!mozilla::gmp::GMPVideoDecoderChild::RecvInitDecode(const GMPVideoCodec & aCodecSettings, nsTArray<unsigned char> && aCodecSpecific, const int & aCoreCount) Line 127	C++
xul.dll!mozilla::gmp::PGMPVideoDecoderChild::OnMessageReceived(const IPC::Message & msg__) Line 414	C++
xul.dll!mozilla::gmp::PGMPContentChild::OnMessageReceived(const IPC::Message & msg__) Line 447	C++


This is a crash in the Windows Media Foundation decoder that we're using. I'm not sure what we can do about that.
Attachment #8693437 - Flags: review?(gsquelart) → review+
Comment on attachment 8693437 [details]
MozReview Request: Bug 1186406 - Log why GMPVideoDecoderParent::Decode() fails. r?gerald

https://reviewboard.mozilla.org/r/26463/#review23877

All good, but... Why "LOGV" (instead of LOGW or LOGE)? Won't they be hidden in most runs?
Comment on attachment 8693438 [details]
MozReview Request: Bug 1186406 - Copy input to ClearKey's decoder, so we can return its containing shmem earlier. r?gerald

https://reviewboard.mozilla.org/r/26465/#review23879

r+ with nits:

::: media/gmp-clearkey/0.1/ClearKeyUtils.h:104
(Diff revision 1)
> +  aVec.clear();
> +  aVec.insert(aVec.begin(), aData, aData + aLength);

`aVec.assign(aData, aData + aLength)` should do the work of both `clear`&`insert`.

::: media/gmp-clearkey/0.1/VideoDecoder.h:67
(Diff revision 1)
> +      , mIsKeyframe(0)

`mIsKeyframe` is a `bool`, please init with `false`.
Attachment #8693438 - Flags: review?(gsquelart) → review+
(In reply to Chris Pearce (:cpearce) from comment #290)
> Also note, with the above fix, I'm still seeing a crash, but this time a lot
> less frequently.
> 
> Mochitest log:
> 
> Test File Name:	Test:	Error message:
> /tests/dom/media/test/test_eme_playback.html	undefined	
> /tests/dom/media/test/test_eme_playback.html	undefined	
> /tests/dom/media/test/test_eme_playback.html	undefined	
> /tests/dom/media/test/test_eme_playback.html	undefined	
> /tests/dom/media/test/test_eme_playback.html	640x480@959kbps with 1st keys
> then 640x480@624kbps with 2nd keys-11: session[].generateRequest(cenc,
> 0000003470737368010000001077efecc0b24d02ace33c1e52e2fb4b000000017e571d037e571
> d037e571d037e571d1200000000) failed; InvalidStateError: Promise still
> outstanding at MediaKeys shutdown	
> /tests/dom/media/test/test_eme_playback.html	640x480@959kbps with 1st keys
> then 640x480@624kbps with 2nd keys-11 got error event; [object Event]	
> /tests/dom/media/test/test_eme_playback.html	400x300 with 1st keys then
> 640x480 with 2nd keys-10 got error event; [object Event]	
> /tests/dom/media/test/test_eme_playback.html	undefined
> 
> 
> Main thread callstack in the GMP process:
> 
> plugin-container.exe!memcpy(unsigned char * dst, unsigned char * src,
> unsigned long count) Line 188	Unknown
> kernel32.dll!_MapPredefinedHandleInternal@16()	Unknown
> kernel32.dll!_RegOpenKeyExInternalW@24()	Unknown
> kernel32.dll!_RegOpenKeyExW@20()	Unknown
> msmpeg2vdec.dll!52f246bc()	Unknown
> [Frames below may be incorrect and/or missing, no symbols loaded for
> msmpeg2vdec.dll]	
> [External Code]	
> clearkey.dll!wmf::WMFH264Decoder::SendMFTMessage(_MFT_MESSAGE_TYPE aMsg,
> unsigned int aData) Line 190	C++
> clearkey.dll!wmf::WMFH264Decoder::Init(int aCoreCount) Line 64	C++
> clearkey.dll!VideoDecoder::InitDecode(const GMPVideoCodec & aCodecSettings,
> const unsigned char * aCodecSpecific, unsigned int aCodecSpecificLength,
> GMPVideoDecoderCallback * aCallback, int aCoreCount) Line 61	C++
> xul.dll!mozilla::gmp::GMPVideoDecoderChild::RecvInitDecode(const
> GMPVideoCodec & aCodecSettings, nsTArray<unsigned char> && aCodecSpecific,
> const int & aCoreCount) Line 127	C++
> xul.dll!mozilla::gmp::PGMPVideoDecoderChild::OnMessageReceived(const
> IPC::Message & msg__) Line 414	C++
> xul.dll!mozilla::gmp::PGMPContentChild::OnMessageReceived(const IPC::Message
> & msg__) Line 447	C++
> 
> 
> This is a crash in the Windows Media Foundation decoder that we're using.
> I'm not sure what we can do about that.

This crash appears to go away when the sandbox is disabled. It makes sense that RegOpenKeyExW is failing when the sandbox is enabled.
Note: We can also fix the kill-switch crash by increasing GMPSharedMem::kGMPBufLimit. Arguably for any value we pick, there's a test file that requires a longer bufLimit, so we're better to fix gmp-clearkey to not hold onto buffers too long, rather than allow GMPs to hold on to too many buffers. So I'll land the patches here.
Bob: Regarding comment 294; it seems the sandbox is killing our gmp-clearkey process on Windows 7 when the platform H.264 decoder tries to call RegOpenKeyExW. I was thinking I could add a hook to intercept that call and return some safe value for that key; maybe cache the value of the keys they try to read at startup, or return a null/safe value. Does that sound reasonable?

We only see the platform H.264 decoder do this intermittently on Windows 7. Other Windows versions seem to not be affected.
Flags: needinfo?(bobowen.code)
(In reply to Chris Pearce (:cpearce) from comment #297)
> Bob: Regarding comment 294; it seems the sandbox is killing our gmp-clearkey
> process on Windows 7 when the platform H.264 decoder tries to call
> RegOpenKeyExW. I was thinking I could add a hook to intercept that call and
> return some safe value for that key; maybe cache the value of the keys they
> try to read at startup, or return a null/safe value. Does that sound
> reasonable?
> 
> We only see the platform H.264 decoder do this intermittently on Windows 7.
> Other Windows versions seem to not be affected.

I don't think I've reproduced the same problem as comment 294, but it fails for me with a debug build from time to time, with:
"This test left crash dumps behind, but we weren't expecting it to!"

I can't see it getting blocked from anything interesting registry wise, just things like "\REGISTRY\MACHINE", "SOFTWARE" and "Microsoft".

These are higher level keys, not anything that I would have thought would be useful.
If I add rules for all keys, which then allows these opens, it doesn't go on to try lower level things.

Also, it seems odd that a block from the sandbox, would cause intermittent issues.

I'll try leaving an opt build test running later to see if I can reproduce.
Flags: needinfo?(bobowen.code)
Right, erm, so I guess you're running these tests with the env var MOZ_WIN_SANDBOX_LOGGING=1 set.

I'm pretty sure that crash you are seeing is a bug in my logging code.

It seems that the Length in UNICODE_STRING that I use is in bytes, even though the buffer pointer in the same structure is effectively a wchar_t* (which is always 2 bytes on Windows).

I'll get that fixed, it shouldn't be affecting anyone who doesn't have that environment variable set.
Flags: needinfo?(cpearce)
Haha, yeah, I do have MOZ_WIN_SANDBOX_LOGGING=1 set. Verifying now, but I expect that's it. Thanks Bob.
Flags: needinfo?(cpearce)
Mass change P2 -> P3
Priority: P2 → P3
Assignee: cpearce → nobody
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: