Bug 275165 – REGRESSION(278498@main) [Skia] getUserMedia(deviceID) frequently freezing in media stream tests under debug

• Component: Media
• Status: RESOLVED FIXED

[Lauro Moura]

Created attachment 471594 [details]
GST_DEBUG=2 output of running the test

Affects multiple MediaStream-related tests, leading to early exits on both GTK and WPE debug bots since early May 2024.

Bisecting with fast/mediastream/get-user-media-device-id.html led to 278498@main, the commit enabling Skia by default in place of Cairo. And indeed building WebKit with `--cmakeargs=-DUSE_SKIA=0` makes the test pass even in that commit.

Further investigation of the test shows it's getting stuck in the last test case of this file, "Ideal deviceId constraints":

```
await navigator.mediaDevices.getUserMedia({video: true});
const devices  = await navigator.mediaDevices.enumerateDevices();
for (let device of devices) {
    if (device.kind === "audioinput") {
        const stream = await navigator.mediaDevices.getUserMedia({audio: {deviceId: device.deviceId}});
        assert_equals(stream.getAudioTracks()[0].getSettings().deviceId, device.deviceId, "Matching audio device id");
    } else if (device.kind === "videoinput") {
        const stream = await navigator.mediaDevices.getUserMedia({video: {deviceId: device.deviceId}});
        assert_equals(stream.getVideoTracks()[0].getSettings().deviceId, device.deviceId, "Matching video device id");
    }
}
```

The test is getting stuck in one of the `await navigator.mediaDevices.getUserMedia(...)` inside the loop, trying to access a specific deviceID, sometimes a video device, sometimes an audio device.

Running with `GST_DEBUG=2` showed these lines among others, not sure if related (full log attached)

```
0:00:01.009301531    47 0x588f78236650 ERROR                  pulse pulsedeviceprovider.c:466:gst_pulse_device_provider_probe:<pulsedeviceprovider0> Failed to connect: Invalid argument
Audio capture was requested but no device was found amongst 3 devices
BooleanConstraint 9, exact -1, ideal 1
MediaConstraint 10 of type 3
Audio capture was requested but no device was found amongst 3 devices
BooleanConstraint 9, exact -1, ideal 1
MediaConstraint 10 of type 3
```

[Lauro Moura]

Update: It's timing out in this test case when running after the other test cases in the same file.

[Lauro Moura]

Looks like the issue is related to multiple calls to getUserMedia. The following test fails on the 6th or 7th iteration, before the other tests


promise_test(async (test) => {
    for (let i = 0; i < 10; i++) {
        console.log(`Dummy getusermedia starting ${i}`);
        await navigator.mediaDevices.getUserMedia({ audio: true, video: true });
        console.log(`Dummy getusermedia returning ${i}`);
    }
}, "Repeated getusermedia calls");


This passes with a Cairo build. A similar standalone html file iterates normally with MiniBrowser in a Skia build.

[Philippe Normand]

Is that failing on 2 bots?

This looks suspicious...:

Failed to create secure directory (/run/user/1000/pulse): Too many levels of symbolic links

[Philippe Normand]

Seems odd this would be related to Skia/Cairo too :(
I can't reproduce this here and can't do debug builds on this laptop.

[Lauro Moura]

(In reply to Philippe Normand from comment #3)
> Is that failing on 2 bots?

Yeah: https://results.webkit.org/?suite=layout-tests&test=fast%2Fmediastream%2Fget-user-media-device-id.html

> 
> This looks suspicious...:
> 
> Failed to create secure directory (/run/user/1000/pulse): Too many levels of
> symbolic links

Oh, I think it comes from my laptop, running ubuntu 23.10. I did not see it in the bots, and it's still present if I do a cairo build, with the test not timing out.

[Lauro Moura]

(In reply to Philippe Normand from comment #4)
> Seems odd this would be related to Skia/Cairo too :(
> I can't reproduce this here and can't do debug builds on this laptop.

Is there any set of variables like GST_DEBUG that I could run to help debugging it?

[Philippe Normand]

GST_DEBUG="3,webkit*:9" GST_DEBUG_FILE=/path/to/logfile.log

[Lauro Moura]

Created attachment 471603 [details]
Detailed logs for skia run

(In reply to Philippe Normand from comment #7)
> GST_DEBUG="3,webkit*:9" GST_DEBUG_FILE=/path/to/logfile.log

This is a log for a skia debug build using the above logging options, alongside GST_DEBUG_NO_COLOR=1

In the next comment I'll add the same for cairo.

[Lauro Moura]

Created attachment 471604 [details]
Detailed logs for cairo run

Cairo version.

[Lauro Moura]

(In reply to Lauro Moura from comment #2)
> Looks like the issue is related to multiple calls to getUserMedia. The
> following test fails on the 6th or 7th iteration, before the other tests
> 
> 
> promise_test(async (test) => {
>     for (let i = 0; i < 10; i++) {
>         console.log(`Dummy getusermedia starting ${i}`);
>         await navigator.mediaDevices.getUserMedia({ audio: true, video: true
> });
>         console.log(`Dummy getusermedia returning ${i}`);
>     }
> }, "Repeated getusermedia calls");
> 

Note: The logs were generated from this test above, with the repeated getUserMedia calls.

[Philippe Normand]

In MockRealtimeVideoSource::generateFrameInternal() if you "return null" before creating the GraphicsContextStateSaver instance, the timeout doesn't happen.

Something looks incorrect in the skia GraphicsContextSkia::save() and/or GraphicsContextSkia::restore() implementations? Maybe?

I don't know about graphics, I can't go any further.

[Carlos Garcia Campos]

So, does this only happen in debug builds? or it's just easy to reproduce? What tests should I run to try to reproduce it?

[Philippe Normand]

I could reproduce this only in Debug builds. 

Add the promise_test from comment 2 to the top (before existing promise_test calls) of fast/mediastream/get-user-media-device-id.html and then the test will time out.

[Carlos Garcia Campos]

Pull request: https://github.com/WebKit/WebKit/pull/29739

[Vitaly Dyackhov]

Pull request: https://github.com/WebKit/WebKit/pull/29745

[Radar WebKit Bug Importer]

<rdar://problem/129685032>

[EWS]

Committed 280450@main (abd2c22d3e30): <https://commits.webkit.org/280450@main>

Reviewed commits have been landed. Closing PR #29739 and removing active labels.

[EWS]

Committed 280712@main (c85534cb863a): <https://commits.webkit.org/280712@main>

Reviewed commits have been landed. Closing PR #29745 and removing active labels.