According to this ini file, these tests are expected to timeout on Android.

When running this try push while simulating GeckoView with e10s-multi, the test does indeed timeout, however it is flagged as an unexpected failure.

I had a chat with jgraham on Matrix and learned that any tests not listed in that ini file are expected to pass, which is applicable here. Sounds like this is indeed a GV issue.

I was comparing a successful test with a failed test, and I noticed the following in the log:

[task 2020-10-19T21:24:58.918Z] 21:24:58     INFO - TEST-START | /mediacapture-record/MediaRecorder-peerconnection.https.html
[task 2020-10-19T21:24:58.934Z] 21:24:58     INFO - Closing window 33
[task 2020-10-19T21:29:13.920Z] 21:29:13     INFO - Got timeout in harness
[task 2020-10-19T21:29:14.076Z] 21:29:14     INFO - TEST-TIMEOUT | /mediacapture-record/MediaRecorder-peerconnection.https.html | took 255158ms
[task 2020-10-19T21:29:14.641Z] 21:29:14     INFO - IOError on command, setting status to CRASH
[task 2020-10-19T21:29:14.641Z] 21:29:14     INFO - Browser not responding, setting status to CRASH
[task 2020-10-19T21:29:14.642Z] 21:29:14  WARNING - Command left in command_queue during cleanup: 'test_ended', (<wptrunner.wpttest.TestharnessTest /mediacapture-record/MediaRecorder-peerconnection.https.html>, (<wptrunner.wpttest.TestharnessResult CRASH>, []))
[task 2020-10-19T21:29:14.642Z] 21:29:14     INFO - Closing logging queue
[task 2020-10-19T21:29:14.642Z] 21:29:14     INFO - queue closed

jgraham, do you have any idea why this timeout has never triggered an orange?

I think just because it's marked as expected in the ini file? The sync will have set that on import.

Okay, so this brings up my next question:
Why is the timeout failing when e10s-multi is turned on?

Could there be some kind of harness issue?

So the log looks like:

[task 2020-10-19T21:28:04.764Z] 21:28:04     INFO - TEST-UNEXPECTED-TIMEOUT | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":true,"audio":false} with format [passthrough]. - Test timed out
[task 2020-10-19T21:28:04.765Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.765Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder gets ondata on stopping recorded tracks {"video":true,"audio":false} with format [passthrough]. - expected PASS
[task 2020-10-19T21:28:04.765Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.765Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":false,"audio":true} with format [passthrough]. - expected PASS
[task 2020-10-19T21:28:04.766Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.766Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder gets ondata on stopping recorded tracks {"video":false,"audio":true} with format [passthrough]. - expected PASS
[task 2020-10-19T21:28:04.766Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.766Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":true,"audio":true} with format [passthrough]. - expected PASS
[task 2020-10-19T21:28:04.767Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.767Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder gets ondata on stopping recorded tracks {"video":true,"audio":true} with format [passthrough]. - expected PASS
[task 2020-10-19T21:28:04.767Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.767Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":false,"audio":true} with format video/webm;codecs=vp8. - expected FAIL
[task 2020-10-19T21:28:04.767Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.768Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.768Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder gets ondata on stopping recorded tracks {"video":false,"audio":true} with format video/webm;codecs=vp8. - expected FAIL
[task 2020-10-19T21:28:04.768Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.768Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.768Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":true,"audio":false} with format video/webm;codecs=vp8. - expected PASS
[task 2020-10-19T21:28:04.769Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.769Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder gets ondata on stopping recorded tracks {"video":true,"audio":false} with format video/webm;codecs=vp8. - expected PASS
[task 2020-10-19T21:28:04.769Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.769Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":true,"audio":true} with format video/webm;codecs=vp8. - expected FAIL
[task 2020-10-19T21:28:04.769Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.770Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.770Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder gets ondata on stopping recorded tracks {"video":true,"audio":true} with format video/webm;codecs=vp8. - expected FAIL
[task 2020-10-19T21:28:04.770Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.771Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.771Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":false,"audio":true} with format video/webm;codecs=vp9. - expected FAIL
[task 2020-10-19T21:28:04.771Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.773Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.773Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder gets ondata on stopping recorded tracks {"video":false,"audio":true} with format video/webm;codecs=vp9. - expected FAIL
[task 2020-10-19T21:28:04.773Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.773Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.773Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":true,"audio":false} with format video/webm;codecs=vp9. - expected FAIL
[task 2020-10-19T21:28:04.773Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.775Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.775Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder gets ondata on stopping recorded tracks {"video":true,"audio":false} with format video/webm;codecs=vp9. - expected FAIL
[task 2020-10-19T21:28:04.775Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.776Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.776Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":true,"audio":true} with format video/webm;codecs=vp9. - expected FAIL
[task 2020-10-19T21:28:04.776Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.777Z] 21:28:04     INFO - 
[task 2020-10-19T21:28:04.777Z] 21:28:04     INFO - TEST-UNEXPECTED-NOTRUN | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder gets ondata on stopping recorded tracks {"video":true,"audio":true} with format video/webm;codecs=vp9. - expected FAIL
[task 2020-10-19T21:28:04.777Z] 21:28:04     INFO - TEST-INFO | expected FAIL
[task 2020-10-19T21:28:04.921Z] 21:28:04     INFO - TEST-TIMEOUT | /mediacapture-record/MediaRecorder-peerconnection.https.html | took 180884ms

So the overall status of the test is TIMEOUT, but it's not unexpected:

[task 2020-10-19T21:28:04.921Z] 21:28:04     INFO - TEST-TIMEOUT | /mediacapture-record/MediaRecorder-peerconnection.https.html | took 180884ms

What is unexpected is some of the subtest statuses:

[task 2020-10-19T21:28:04.764Z] 21:28:04     INFO - TEST-UNEXPECTED-TIMEOUT | /mediacapture-record/MediaRecorder-peerconnection.https.html | PeerConnection MediaRecorder receives data after onstart, {"video":true,"audio":false} with format [passthrough]. - Test timed out

The format of these lines in TEST[-UNEXPECTED]?-<status> | <test id> | <subtest name> - <msg>. It's not great, but it's the best thing that was possible given the need to be compatible with old regex based parsing. So in this case the unexpected result is in the subtest PeerConnection MediaRecorder receives data after onstart, {"video":true,"audio":false} with format [passthrough].. That specific subtest isn't mentioned in [1], so it's expected to pass.

[1] https://searchfox.org/mozilla-central/source/testing/web-platform/meta/mediacapture-record/MediaRecorder-peerconnection.https.html.ini

Hey Andreas,

This is a follow-up to the discussion on Matrix. I made two try pushes, the first with single-process e10s, the second with multi-process e10s.

Both tests ran with signaling:3 turned on. I have attached their logs above for posterity.

Do you see anything in these logs that might help with troubleshooting this?

First of all, the log with the single-process e10s that passes does not mention MediaRecorder-peerconnection.https.html.

In the failure log though, there is a number of:

10-22 23:34:35.030 31874 31892 I Gecko : [Child 31874: Unnamed thread 0x771ccb01e890]: E/signaling [|WebrtcVideoSessionConduit] VideoConduit.cpp:2041: DeliverPacket DeliverPacket Failed, 1
10-22 23:34:35.030 31874 31892 I Gecko : [Child 31874: Unnamed thread 0x771ccb01e890]: E/signaling [|WebrtcVideoSessionConduit] VideoConduit.cpp:2129: ReceivedRTPPacket RTP Processing Failed

Then they go away, and we seem to actually start the MediaRecorder, because I also see:

10-22 23:34:35.383 31874 31948 I Gecko : [Child 31874, Unnamed thread 771cb88629a0] WARNING: NS_ENSURE_SUCCESS(rv, NS_ERROR_FAILURE) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/dom/media/encoder/VP8TrackEncoder.cpp:473

This error is from any of the lines marked in [1]. And depending on which, it could be from any line in [2] or [3].

[1] https://searchfox.org/mozilla-central/rev/ff85081e3b05f89f9a5921b489b6e01ed4a88c25/dom/media/encoder/VP8TrackEncoder.cpp#342,371,384
[2] https://searchfox.org/mozilla-central/rev/ff85081e3b05f89f9a5921b489b6e01ed4a88c25/dom/media/encoder/VP8TrackEncoder.cpp#64,76,88
[3] https://searchfox.org/mozilla-central/rev/ff85081e3b05f89f9a5921b489b6e01ed4a88c25/dom/media/ImageToI420.cpp#116,121,126

VP8TrackEncoder:5 logs might help with this. Perhaps best to set it via the pref logging.VP8TrackEncoder=5 for this test only so as to not cause too much spam.

If I were to guess we unexpectedly get a frame with either an invalid frame size, an unexpectedly large frame size, or a reasonable frame size but we for some other reason cannot allocate a buffer for encoding it. VP8TrackEncoder:5 logs would tell us which, if any, of these.

STR for this is to apply the patchset in bug 1654817, rebuild, then run the MediaRecorder-peerconnection.https.html test.

This test is timing out because we can't convert the image received from the peer connection to an I420 software-backed frame for encoding.
We are hitting this path.

This seems to me like the same cause as for bug 1526207, since we use WebrtcMediaDataDecoder on Android now.

Why this worked for e10s-single I don't know. Do we have evidence the test actually ran (and passed) there?

(In reply to Andreas Pehrson [:pehrsons] from comment #13)

Why this worked for e10s-single I don't know. Do we have evidence the test actually ran (and passed) there?

It actually timed out under e10s-single as well, but for some reason it did so differently. See comment 4 and comment 5.

Based on your information, it looks like the affected subtest(s) are safe to mark as expected to timeout?

(In reply to Aaron Klotz [:aklotz] from comment #14)

Based on your information, it looks like the affected subtest(s) are safe to mark as expected to timeout?

Yes. But let's keep a bug depending on bug 1649110 open so we know to check that these work again with 1649110 fixed.

(In reply to Andreas Pehrson [:pehrsons] from comment #15)

Yes. But let's keep a bug depending on bug 1649110 open so we know to check that these work again with 1649110 fixed.

I filed bug 1674174 for the expectation changes, leaving this open for the follow-up checks.

Thanks!