Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Short videos dispatch loadedmetadata before the metadata is present #31415

Open
jdm opened this issue Feb 23, 2024 · 66 comments · May be fixed by #31706
Open

Short videos dispatch loadedmetadata before the metadata is present #31415

jdm opened this issue Feb 23, 2024 · 66 comments · May be fixed by #31706

Comments

@jdm
Copy link
Member

jdm commented Feb 23, 2024

This is the cause of the failure in the WPT test video_size_preserved_after_ended.html. The video's actual size is obtained when gstreamer sends a player event with the video metadata present (

video_elem.set_video_width(metadata.width);
video_elem.set_video_height(metadata.height);
). For most videos, this causes Servo to dispatch the loadedmetadata DOM event because we change the element's ready state to HaveMetadata.

However, HTMLMediaElement has a special case when the network response EOF is reached and the element's ready state is still HaveNothing (

if elem.ready_state.get() == ReadyState::HaveNothing {
// Make sure that we don't skip the HaveMetadata and HaveCurrentData
// states for short streams.
elem.change_ready_state(ReadyState::HaveMetadata);
}
). We change the ready state to HaveMetadata without waiting for the media player's metadata event, so the video element's properties do not reflect the actual metadata yet.

@gterzian
Copy link
Member

gterzian commented Mar 5, 2024

The state machine for this is quite complicated, but specified via https://html.spec.whatwg.org/multipage/media.html#ready-states

In some ways it appears our internal state machine is tied to closely to the outer one(available to JS via [readyState](https://html.spec.whatwg.org/multipage/media.html#dom-media-readystate)). We may need to add some additional unspecified variants to ReadyState which reflect this particular intermediary state.

Requires a good look at the code and spec...

@pylbrecht
Copy link
Sponsor Contributor

I feel like giving this a try.

@pylbrecht
Copy link
Sponsor Contributor

Just to be transparent about my progress: I have been and still am studying the spec and code to get a better understanding of the problem.

On a general note, my situation (kids, full-time job) only allows for small time windows each day to work on contributions. So my progress is usually slow, but steady.

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Mar 10, 2024

All right, here is what I understood so far.

From https://html.spec.whatwg.org/multipage/media.html#media-data-processing-steps-list:

Once enough of the media data has been fetched to determine the duration of the media resource, its dimensions, and other metadata

We set the dimensions and queue a resize event

video_elem.set_video_width(metadata.width);
video_elem.set_video_height(metadata.height);
let window = window_from_node(self);
let task_source = window.task_manager().media_element_task_source();
task_source.queue_simple_event(self.upcast(), atom!("resize"), &window);

We set the ready state to HaveMetadata,

video_elem.set_video_width(metadata.width);
video_elem.set_video_height(metadata.height);
let window = window_from_node(self);
let task_source = window.task_manager().media_element_task_source();
task_source.queue_simple_event(self.upcast(), atom!("resize"), &window);
}
}
// Step 6.
self.change_ready_state(ReadyState::HaveMetadata);

which in turn queues a loadedmetadata event.

match (old_ready_state, ready_state) {
(ReadyState::HaveNothing, ReadyState::HaveMetadata) => {
task_source.queue_simple_event(self.upcast(), atom!("loadedmetadata"), &window);
// No other steps are applicable in this case.
return;
},

Before this loadedmetadata event is handled, we reach EOF and "blindly" set the ready state to HaveMetadata without waiting for the loadedmetadata event being handled.

if elem.ready_state.get() == ReadyState::HaveNothing {
// Make sure that we don't skip the HaveMetadata and HaveCurrentData
// states for short streams.
elem.change_ready_state(ReadyState::HaveMetadata);
}

This means we need to make sure that we handle that loadedmetadata event, before we set the ready state to HaveMetadata in process_response_eof().


And now I'm lost. How can we achieve that?

We may need to add some additional unspecified variants to ReadyState which reflect this particular intermediary state.

@gterzian, I understand your suggestion on a high level, but I don't feel confident enough introducing this into the state machine, yet.

One big picture thing I am missing: where do we handle these queued events?
Maybe you can point me to the relevant parts in the spec and/or code.

Things I skimmed so far:

@gterzian
Copy link
Member

gterzian commented Mar 11, 2024

One big picture thing I am missing: where do we handle these queued events?

When we do something like task_source.queue_simple_event(self.upcast(), atom!("loadedmetadata"), &window); , we are queueing a task just to fire--synchronously inside the task-- the event. The event can then be handled by the JS, for example as is done in the test.

I think the problem is essentially a mismatch between how we handle the networking messages, like eof, and how we handle the player events.

For clarity, the networking stuff is handled through FetchResponseListener, and the player events are handled via a callback on the IPC router.

So the problem is the interaction between the handling of the network response eof, and the handling of the PlayerEvent::MetadataUpdated, where we change the readystate to ReadyState::HaveMetadata if the current state is ReadyState::HaveNothing. Instead, we should only do this at

self.change_ready_state(ReadyState::HaveMetadata);

I assume that simply removing the above will result in other tests failing. So the exact fix, how to resolve the handling of the response eof and the handling of the PlayerEvent::MetadataUpdated, probably requires looking more closely at the spec, and trial and error while running the test.

@pylbrecht
Copy link
Sponsor Contributor

Thanks a lot for that detailed response, @gterzian.

I think the problem is essentially a mismatch between how we handle the networking messages, like eof, and how we handle the player events.

This is a very helpful insight! ☝️

I will go back to my cave to process (and most likely come back with more questions).

@jdm
Copy link
Member Author

jdm commented Mar 12, 2024

https://html.spec.whatwg.org/multipage/media.html#concept-media-load-resource is the relevant spec text. In particular:

Let processEndOfMedia be the following step: If the fetching process has completes without errors, including decoding the media data, and if all of the data is available to the user agent without network access, then, the user agent must move on to the final step below. This might never happen, e.g. when streaming an infinite resource such as web radio, or if the resource is longer than the user agent's ability to cache data.

@jdm
Copy link
Member Author

jdm commented Mar 12, 2024

Further down the page, this step looks interesting: "Once the entire media resource has been fetched (but potentially before any of it has been decoded)"

@gterzian
Copy link
Member

gterzian commented Mar 12, 2024

I've had another look at the spec, and there are two separate things:

  1. How network state changes: https://html.spec.whatwg.org/multipage/media.html#dom-media-networkstate
  2. How the ready state changes: https://html.spec.whatwg.org/multipage/media.html#ready-states:media-element

elem.change_ready_state(ReadyState::HaveMetadata);

Above corresponds to "Once the entire media resource has been fetched (but potentially before any of it has been decoded)". This should indeed fire the suspend event(the progress event is fired periodically, and actually perhaps it should be removed from eof), and set NetworkState::Idle.

But, that step should not do anything with the ready state. Instead, this should be done as part of the below

fn handle_player_event(&self, event: &PlayerEvent) {

@pylbrecht
Copy link
Sponsor Contributor

Thanks, now things are starting to take shape.

How do you find the relevant sections (presumably without much effort) in the spec?
Experience? Or do you just read it top to bottom and try to correlate code to sections?

@gterzian
Copy link
Member

gterzian commented Mar 14, 2024

Thanks, now things are starting to take shape.

Good! Let me know if you have more questions or get stuck, I have a pretty clear idea where the changes should be but don't want to spoil the fun for you.

How do you find the relevant sections (presumably without much effort) in the spec?

It can be quite hard if the spec changed and/or our implementation does not comform. I find the firing of events to be pretty clear tags. If the spec mentions one, you can find it in Servo by searching for atom!("eventname").

So let's say I rather look for the relevant part in the code, after looking at the spec.

If you're lucky there are clear links to the spec in the code and you can search for that...

@pylbrecht
Copy link
Sponsor Contributor

Good! Let me know if you have more questions or get stuck, I have a pretty clear idea where the changes should be but don't want to spoil the fun for you.

Thanks, very much appreciated! 😁

It can be quite hard if the spec changed and/or our implementation does not comform. I find the firing of events to be pretty clear tags. If the spec mentions one, you can find it in Servo by searching for atom!("eventname").

That's a great insight, thanks.

@pylbrecht pylbrecht linked a pull request Mar 15, 2024 that will close this issue
4 tasks
@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Mar 15, 2024

After some intense cross-referencing of the spec on ready states I saw that this state transition was not implemented at all:

If the previous ready state was HAVE_FUTURE_DATA or more, and the new ready state is HAVE_CURRENT_DATA or less

So I gave it a try. The test is now failing at video_size_preserved_after_ended.html#26:

/html/semantics/embedded-content/the-video-element/video_size_preserved_after_ended.html
  FAIL Video dimensions are preserved at the end of the video. - assert_equals: expected 1 but got 2

I guess that's progress!
However I am too tired to investigate that failure today. I will come back to this tomorrow.


if self.is_potentially_playing()
&& !self.Ended()
&& !self.is_paused_for_in_band_content()
&& !self.is_paused_for_user_interaction()

Since some of these methods are just dummy implementations (e.g. is_paused_for_in_band_content() or is_paused_for_user_interaction()), I was not too confident that this would work out of the box in the first place (even though it might be unrelated to the failing assertion).

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Mar 16, 2024

Found this in the spec:

If at any time the user agent learns that an audio or video track has ended and all media data relating to that track corresponds to parts of the media timeline that are before the earliest possible position, the user agent may queue a media element task given the media element to run these steps:

  1. Remove the track from the audioTracks attribute's AudioTrackList object or the videoTracks attribute's VideoTrackList object as appropriate.

  2. Fire an event named removetrack at the media element's aforementioned AudioTrackList or VideoTrackList object, using TrackEvent, with the track attribute initialized to the AudioTrack or VideoTrack object representing the track.

Looks like this is not covered yet:

% rg "\bremovetrack\b" --glob '**/*.rs'
components/script/dom/videotracklist.rs
162:    event_handler!(removetrack, GetOnremovetrack, SetOnremovetrack);

components/script/dom/audiotracklist.rs
146:    event_handler!(removetrack, GetOnremovetrack, SetOnremovetrack);

components/script/dom/texttracklist.rs
107:            .fire_event(atom!("removetrack"));
140:    event_handler!(removetrack, GetOnremovetrack, SetOnremovetrack);

components/script/dom/mediastream.rs
142:    /// <https://w3c.github.io/mediacapture-main/#dom-mediastream-removetrack>

I am not sure if this is the cause for the assertion to fail, but it looks like we are not removing a video track, where we should be. 🤔

@gterzian
Copy link
Member

Great, sounds like you are on the right track and it just needs some further investigation!

@pylbrecht
Copy link
Sponsor Contributor

More digging..

If at any time the user agent learns that an audio or video track has ended and all media data relating to that track corresponds to parts of the media timeline that are before the earliest possible position, the user agent may queue a media element task given the media element to run these steps:

I don't know how to translate the highlighted condition to code.
While looking for some copy/pastable inspiration related to the "media timeline", I found these:

// Step 1.
// servo-media owns the media timeline.
// Step 2.
// XXX(ferjm) Update the timeline offset.

Then I took a brief detour into servo-media's code, but could not easily relate anything to the spec. I might need to spend more time on that. However, I might not even need that to solve the issue at hand.

If at any time the user agent learns that an audio or video track has ended

I suppose this is probably true for a bunch of places. I marked two of them in dbca037.

Next steps: remove video track and fire a removetrack event.

@gterzian
Copy link
Member

I might need to spend more time on that. However, I might not even need that to solve the issue at hand.

Sounds about right! I think it's a good idea to go for a specific fix, and leave TODOS and open issues for other stuff you come across. Off-course if a change in one place starts breaking something else, and that you see a fix for that, it's worth doing it in one PR.

@pylbrecht
Copy link
Sponsor Contributor

I put together a hacky solution passing video_size_preserved_after_ended.html locally to get some feedback via ./mach try wpt. Turns out there are a lot of TIMEOUTs now (with the occasional FAIL and PASS here and there):

Could many TIMEOUTs be some sort of heuristic for a general issue in the code (e.g. panics)?
If not, does it suffice to investigate only unexpected TIMEOUTs and FAILs?

I am wondering how deep I need to go into the avalanche of failing tests caused by my changes.

@mrobinson
Copy link
Member

Clicking into the test runs, it looks like the timeouts might be related to GStreamer not behaving properly on the CI:

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
  │ 
  │ ALSA lib confmisc.c:855:(parse_card) cannot find card '0'
  │ ALSA lib conf.c:5178:(_snd_config_evaluate) function snd_func_card_inum returned error: No such file or directory
  │ ALSA lib confmisc.c:422:(snd_func_concat) error evaluating strings
  │ ALSA lib conf.c:5178:(_snd_config_evaluate) function snd_func_concat returned error: No such file or directory
  │ ALSA lib confmisc.c:1334:(snd_func_refer) error evaluating name
  │ ALSA lib conf.c:5178:(_snd_config_evaluate) function snd_func_refer returned error: No such file or directory
  │ ALSA lib conf.c:5701:(snd_config_expand) Evaluate error: No such file or directory
  │ ALSA lib pcm.c:2664:(snd_pcm_open_noupdate) Unknown PCM default
  │ AL lib: (EE) ALCplaybackAlsa_open: Could not open playback device 'default': No such file or directory
  │ Cannot connect to server socket err = No such file or directory
  │ Cannot connect to server request channel
  │ jack server is not running or cannot be started
  │ JackShmReadWritePtr::~JackShmReadWritePtr - Init not done for -1, skipping unlock
  │ JackShmReadWritePtr::~JackShmReadWritePtr - Init not done for -1, skipping unlock
  │ ALSA lib confmisc.c:855:(parse_card) cannot find card '0'
  │ ALSA lib conf.c:5178:(_snd_config_evaluate) function snd_func_card_inum returned error: No such file or directory
  │ ALSA lib confmisc.c:422:(snd_func_concat) error evaluating strings
  │ ALSA lib conf.c:5178:(_snd_config_evaluate) function snd_func_concat returned error: No such file or directory
  │ ALSA lib confmisc.c:1334:(snd_func_refer) error evaluating name
  │ ALSA lib conf.c:5178:(_snd_config_evaluate) function snd_func_refer returned error: No such file or directory
  │ ALSA lib conf.c:5701:(snd_config_expand) Evaluate error: No such file or directory
  │ ALSA lib pcm.c:2664:(snd_pcm_open_noupdate) Unknown PCM default
  │ AL lib: (EE) ALCplaybackAlsa_open: Could not open playback device 'default': No such file or directory
  │   ▶ TIMEOUT [expected FAIL] A track appended after the initial track configuration does not change other tracks
  └   └   → Test timed out

What happens when you run those tests locally?

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Mar 22, 2024

/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html times out locally as well (however without the ALSA errors).

Output with --headless

~/dev/personal/servo/servo  שׂ ready-states
% ./mach test-wpt --headless tests/wpt/tests/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.20 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.20 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.20 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.20 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.20 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.20 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.20 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.20 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.20 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.20 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.21 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.21 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.21 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.21 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.42 SUITE_START: web-platform-test - running 1 tests
 0:01.42 INFO Using 1 child processes
 0:01.42 INFO Starting runner
 0:01.60 TEST_START: /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:01.60 WARNING Got command init_succeeded in state running
 0:12.39 TEST_END: Test TIMEOUT, expected OK. Subtests passed 0/1. Unexpected 1
TIMEOUT A track appended after the initial track configuration does not change other tracks - Test timed outTIMEOUT /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:12.39 INFO No more tests
 0:12.39 INFO No more tests
 0:12.39 INFO Closing logging queue
 0:12.39 INFO queue closed
 0:12.43 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 2 checks (1 subtests, 1 tests)
Expected results: 0
Unexpected results: 2
  test: 1 (1 timeout)
  subtest: 1 (1 timeout)

Unexpected Results
------------------
/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
  TIMEOUT A track appended after the initial track configuration does not change other tracks - Test timed out
  TIMEOUT /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:12.43 INFO Got 1 unexpected results, with 0 unexpected passes
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:12.44 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:12.44 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:12.44 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:12.44 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:12.44 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:12.48 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:12.48 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:12.86 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:12.93 INFO Closing logging queue
 0:12.93 INFO queue closed

Output without --headless

~/dev/personal/servo/servo  שׂ ready-states
% ./mach test-wpt tests/wpt/tests/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.22 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.22 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.22 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.23 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.23 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.23 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.23 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.23 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.41 SUITE_START: web-platform-test - running 1 tests
 0:01.41 INFO Using 1 child processes
 0:01.41 INFO Starting runner
 0:01.58 TEST_START: /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:01.59 WARNING Got command init_succeeded in state running
 0:02.87 pid:32958 Full command: /Users/palbrecht/dev/personal/servo/servo/target/debug/servo --hard-fail -u Servo/wptrunner --ignore-certificate-errors http://web-platform.test:8000/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html -Z replace-surrogates --user-stylesheet /Users/palbrecht/dev/personal/servo/servo/resources/ahem.css --certificate-path /Users/palbrecht/dev/personal/servo/servo/tests/wpt/tests/tools/certs/cacert.pem
pid:32958 UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
 0:17.54 INFO Pausing until the browser exits
 0:17.55 TEST_END: Test TIMEOUT, expected OK. Subtests passed 0/1. Unexpected 1
TIMEOUT A track appended after the initial track configuration does not change other tracks - Test timed outTIMEOUT /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:17.55 INFO Pausing until the browser exits
 0:17.55 INFO No more tests
 0:17.55 INFO No more tests
 0:17.55 INFO Closing logging queue
 0:17.55 INFO queue closed
 0:17.57 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 2 checks (1 subtests, 1 tests)
Expected results: 0
Unexpected results: 2
  test: 1 (1 timeout)
  subtest: 1 (1 timeout)

Unexpected Results
------------------
/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
  TIMEOUT A track appended after the initial track configuration does not change other tracks - Test timed out
  TIMEOUT /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:17.57 INFO Got 1 unexpected results, with 0 unexpected passes
 0:17.69 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:17.94 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:17.94 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:17.94 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:17.94 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:17.94 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:17.95 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:17.95 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:17.95 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:18.02 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:18.02 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:18.07 INFO Closing logging queue
 0:18.07 INFO queue closed

I was reaching out to CI for feedback, because I am running on a Mac M2 and I read on Zulip that this might give flaky results (which it did for me locally; sometimes a test would pass and sometimes it would time out).

@mrobinson
Copy link
Member

I was reaching out to CI for feedback, because I am running on a Mac M2 and I read on Zulip that this might give flaky results (which it did for me locally; sometimes a test would pass and sometimes it would time out).

If you are able to reproduce the flakiness locally, you should be able to dig in a bit to see why the test sometimes times out. It's likely that there is some timing issue that your change introduces or uncovers.

@pylbrecht
Copy link
Sponsor Contributor

Just for the record: I only "verified" flakiness with this test: video_size_preserved_after_ended.html, as I was always running it to get feedback on my changes. I haven't tried any other test cases locally up until now.
Nevertheless, that does not rule out any timing issues caused by my changes, so I will start digging! Thanks!

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Mar 23, 2024

I ran some of the tests against upstream/main and they are still timing out; usually with the following:

UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable

I haven't tried ./mach try wpt against upstream/main, but at this point I think it's safe to assume it's my local setup. 😞

Full output

~/dev/personal/servo/servo  שׂ remotes/upstream/main
% ./mach test-wpt --headless tests/wpt/tests/html/semantics/embedded-content/media-elements/track/
No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
Running 141 tests in web-platform-tests

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/006.html
  │
  └ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/018.html
  │
  └ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/020.html
  │
  └ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/008.html
  │
  └ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/004.html
  │
  └ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/007.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/009.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: No CORS, not same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/040.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, same-origin, no headers, redirects to not same-origin, no headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/012.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, not same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/010.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, not same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/031.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, not same-origin, no headers, redirects to not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/013.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/011.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/016.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, no headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/003.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: No CORS, same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/014.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: No CORS, same-origin, no headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/024.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, not same-origin, with headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/030.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, same-origin, with headers, redirects to not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/041.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, same-origin, with headers, redirects to not same-origin, with headers, redirects to same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/015.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: No CORS, same-origin, with headers, redirects to same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/042.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, same-origin, no headers, redirects to not same-origin, with headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/017.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, no headers, redirects to same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/019.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, same-origin, with headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/029.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, same-origin, no headers, redirects to not same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/005.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/022.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, not same-origin, with headers, redirects to same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/033.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, not same-origin, with headers, redirects to not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/034.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, not same-origin, no headers, redirects to not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/026.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: No CORS, same-origin, with headers, redirects to not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/045.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, same-origin, no headers, redirects to same-origin, no headers, redirects to not same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/043.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, no headers, redirects to same-origin, no headers, redirects to not same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/028.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, with headers, redirects to not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/021.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, not same-origin, with headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/027.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, no headers, redirects to not same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/032.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, not same-origin, with headers, redirects to not same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/023.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, not same-origin, no headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/039.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, no headers, redirects to not same-origin, with headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/046.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, same-origin, no headers, redirects to same-origin, no headers, redirects to not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/035.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, not same-origin, with headers, redirects to not same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/025.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, not same-origin, with headers, redirects to same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/037.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, no headers, redirects to not same-origin, no headers, redirects to same-origin, no headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/036.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Use Credentials, not same-origin, with headers, redirects to not same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/038.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, with headers, redirects to not same-origin, with headers, redirects to same-origin, with headers
  └   └   → Test timed out

  ▶ TIMEOUT [expected OK] /html/semantics/embedded-content/media-elements/track/track-element/cors/044.html
  │
  │ UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
  │   ▶ TIMEOUT [expected PASS] track CORS: Anonymous, same-origin, no headers, redirects to same-origin, no headers, redirects to not same-origin, with headers
  └   └   → Test timed out

Ran 141 tests finished in 167.7 seconds.
  • 97 ran as expected. 0 tests skipped.
  • 44 tests timed out unexpectedly
  • 39 tests had unexpected subtest results

// edit
Waiting for the output of ./mach try running against upstream/main now (https://github.com/pylbrecht/servo/actions/runs/8400369948).

// edit 2
Tests are passing for upstream/main. Looks like I need to set up my Linux VPS again and develop remotely, if I want to work test-driven-ish. 😞

@pylbrecht
Copy link
Sponsor Contributor

Most of the TIMEOUTs I am experiencing locally seem to be just flaky. The tests in the "Stable unexpected results" section have been showing consistent results locally. (Thanks again @mrobinson for supporting on Zulip.)

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Mar 25, 2024

I spend the last days studying the spec and code more. Now I think I really understand what this statement means:

So the problem is the interaction between the handling of the network response eof, and the handling of the PlayerEvent::MetadataUpdated, where we change the readystate to ReadyState::HaveMetadata if the current state is ReadyState::HaveNothing

I am still trying to fully grasp what parts of the spec should be handled in HTMLMediaElementFetchListener and what in HTMLMediaElement.handle_player_event(), as we implement some parts of if in one and some parts in the other.
(Handling ready states clearly is done in handle_player_event(), but there is a lot more besides that.)

I will bang my head against the wall for another day or two and if I don't get anywhere I will reach out with questions again.

@jdm
Copy link
Member Author

jdm commented Apr 2, 2024

I would probably start by logging all of the PlayerEvent updates that are received to understand what streamer (via servo-mdedia) is producing.

@gterzian
Copy link
Member

gterzian commented Apr 3, 2024

I think I am ready for another hint (unless it will take away all the fun; then I will keep banging my head against the wall a little longer!).

Couple of things I'm thinking of:

  1. I don't see ReadyState::HaveCurrentData of HaveFutureData being set anywhere(they may not really matter).
  2. For the "loadeddata" event to fire we need a transition matching (ReadyState::HaveMetadata, new) if new >= ReadyState::HaveCurrentData.
  3. Your PR removes one instance of such a transition, with only one remaining.
  4. There are a couple of player events where we don't set any ready states when handling them, and I think we should. In particular, see the handling of PlayerEvent::EnoughData.
  5. We need to make sure the player events come in at the expected order. For example I hope that PlayerEvent::MetadataUpdated comes indeed first and is not skipped for short streams.

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Apr 3, 2024

@jdm, @gterzian, thanks a lot for the motivational fuel!
I will go back to my dungeon then. 👨‍💻

@pylbrecht
Copy link
Sponsor Contributor

Heartbeat: I spent the last couple of days offline with my family; no measurable progress.
I plan to put in some hours in the next days.

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Apr 10, 2024

Leaving some of my investigative thoughts here:

  1. There are a couple of player events where we don't set any ready states when handling them, and I think we should. In particular, see the handling of PlayerEvent::EnoughData.

PlayerEvent::EnoughData and PlayerEvent::NeedData are used for flow control.
From the GStreamer docs:

Furthermore, in push mode, the application can choose to be blocked in the push function when enough data has already been provided, or it can listen to the enough-data and need-data signals to control flow.

If we get a PlayerEvent::EnoughData, we probably can say the media is at least at ReadyState::HaveCurrentData because the player has enough data to start playback. I don't think it's safe to assume ReadyState::HaveEnoughData, because the player might still need data; just not at that point in time.

I am still wondering if our current player implementation can even signal that it buffered the entire media. I think that would be the signal to set the ready state to ReadyState::HaveEnoughData.

If we get a PlayerEvent::NeedData, we might need to fall back to the most recent "no data" ready state as such:

if self.ready_state < ReadyState::HaveMetadata {
    self.change_ready_state(ReadyState::HaveNothing);
} else {
    self.change_ready_state(ReadyState::HaveMetadata);
}

@gterzian
Copy link
Member

If we get a PlayerEvent::EnoughData, we probably can say the media is at least at ReadyState::HaveCurrentData because the player has enough data to start playback. I don't think it's safe to assume ReadyState::HaveEnoughData, because the player might still need data; just not at that point in time.

In terms of firing the "loadeddata" event, a transition matching (ReadyState::HaveMetadata, new) if new >= ReadyState::HaveCurrentData is needed, so ReadyState::HaveCurrentData will do. Also note we're not setting ReadyState::HaveCurrentData anywhere at this point.

If we get a PlayerEvent::NeedData, we might need to fall back to the most recent "no data" ready state as such:

Yes something along those lines seems like a good idea.

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Apr 12, 2024

track-mode-not-changed-by-new-track.html is really giving me a hard time.
We reach ReadyState::HaveEnoughData, but the test is still timing out here:

Output of track-mode-not-changed-by-new-track.html

% RUST_LOG="script::dom::htmlmediaelement" ./mach test-wpt --headless html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html | tee track-mode-not-changed-by-new-track.log
No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.22 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.22 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.22 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.23 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.24 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.24 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.24 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.45 SUITE_START: web-platform-test - running 1 tests
 0:01.45 INFO Using 1 child processes
 0:01.45 INFO Starting runner
 0:01.61 TEST_START: /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:01.61 WARNING Got command init_succeeded in state running
 0:02.51 pid:25582 Full command: /Users/palbrecht/dev/personal/servo/servo/target/debug/servo --hard-fail -u Servo/wptrunner --ignore-certificate-errors -z http://web-platform.test:8000/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html -Z replace-surrogates --user-stylesheet /Users/palbrecht/dev/personal/servo/servo/resources/ahem.css --certificate-path /Users/palbrecht/dev/personal/servo/servo/tests/wpt/tests/tools/certs/cacert.pem
pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] process_response(Ok(Filtered { filtered: Basic(Metadata { final_url: "http://web-platform.test:8000/media/test... (bc5326deb34eb564)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-192843/192844", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Fri, 12 Apr 2024 09:14:22 GMT", "content-length": "192844"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/seman... (d59f02baea450a95)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false }), unsafe_: Metadata { final_url: "http://web-platform.test:8000/media/test... (bc5326deb34eb564)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-192843/192844", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Fri, 12 Apr 2024 09:14:22 GMT", "content-length": "192844"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/seman... (d59f02baea450a95)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false } }))
 0:02.51 pid:25582 [2024-04-12T09:14:22Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.51 pid:25582 [2024-04-12T09:14:22Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] process_response_eof(Ok(ResourceFetchTiming { domain_lookup_start: 1712913262760009000, timing_check_passed: true, timing_type: Resource, redirect_count: 0, request_start: 1712913262759938000, secure_connection_start: 0, response_start: 0, fetch_start: 1712913262759906000, response_end: 1712913262761694000, redirect_start: 0, redirect_end: 0, connect_start: 41175065, connect_end: 41175065, start_time: 1712913262759906000 }))
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:02.51 pid:25582 [2024-04-12T09:14:22Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Paused)
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Handling player event NeedData
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Paused)
 0:02.51 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Sending media session event playback state changed to Paused
 0:02.64 pid:25582 [2024-04-12T09:14:22Z TRACE script::dom::htmlmediaelement] Player event MetadataUpdated(Metadata { duration: None, width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (Main Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.64 pid:25582 [2024-04-12T09:14:22Z TRACE script::dom::htmlmediaelement] Player event MetadataUpdated(Metadata { duration: Some(6.0272s), width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (Main Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.64 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Handling player event MetadataUpdated(Metadata { duration: None, width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (Main Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.64 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveNothing to HaveMetadata
 0:02.64 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Handling player event MetadataUpdated(Metadata { duration: Some(6.0272s), width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (Main Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.64 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveMetadata to HaveMetadata
 0:02.64 pid:25582 [2024-04-12T09:14:22Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.64 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:02.64 pid:25582 [2024-04-12T09:14:22Z TRACE script::dom::htmlmediaelement] Player event SeekDone(0)
 0:02.64 pid:25582 [2024-04-12T09:14:22Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Paused)
 0:02.64 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Handling player event SeekDone(0)
 0:02.64 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Paused)
 0:02.64 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveMetadata to HaveEnoughData
 0:02.64 pid:25582 [2024-04-12T09:14:22Z DEBUG script::dom::htmlmediaelement] Sending media session event playback state changed to Paused
 0:12.52 TEST_END: Test TIMEOUT, expected OK. Subtests passed 0/1. Unexpected 1
TIMEOUT A track appended after the initial track configuration does not change other tracks - Test timed outTIMEOUT /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:12.52 INFO No more tests
 0:12.52 INFO No more tests
 0:12.52 INFO Closing logging queue
 0:12.52 INFO queue closed
 0:12.56 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 2 checks (1 subtests, 1 tests)
Expected results: 0
Unexpected results: 2
  test: 1 (1 timeout)
  subtest: 1 (1 timeout)

Unexpected Results
------------------
/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
  TIMEOUT A track appended after the initial track configuration does not change other tracks - Test timed out
  TIMEOUT /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:12.56 INFO Got 1 unexpected results, with 0 unexpected passes
 0:12.96 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:12.96 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:12.97 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:12.97 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:12.97 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:12.97 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:12.97 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:12.97 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:12.99 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:13.02 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:13.03 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:13.07 INFO Closing logging queue
 0:13.07 INFO queue closed

video_size_preserved_after_ended.html is still passing.

Ouput of video_size_preserved_after_ended.html

% RUST_LOG="script::dom::htmlmediaelement" ./mach test-wpt --headless tests/wpt/tests/html/semantics/embedded-content/the-video-element/video_size_preserved_after_ended.html | tee video_size_preserved_after_ended.log
No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.23 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.24 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.24 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.24 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.24 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.24 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.25 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.45 SUITE_START: web-platform-test - running 1 tests
 0:01.45 INFO Using 1 child processes
 0:01.45 INFO Starting runner
 0:01.63 TEST_START: /html/semantics/embedded-content/the-video-element/video_size_preserved_after_ended.html
 0:01.63 WARNING Got command init_succeeded in state running
 0:02.42 pid:33921 Full command: /Users/palbrecht/dev/personal/servo/servo/target/debug/servo --hard-fail -u Servo/wptrunner --ignore-certificate-errors -z http://web-platform.test:8000/html/semantics/embedded-content/the-video-element/video_size_preserved_after_ended.html -Z replace-surrogates --user-stylesheet /Users/palbrecht/dev/personal/servo/servo/resources/ahem.css --certificate-path /Users/palbrecht/dev/personal/servo/servo/tests/wpt/tests/tools/certs/cacert.pem
pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] process_response(Ok(Filtered { filtered: Basic(Metadata { final_url: "http://web-platform.test:8000/media/test... (1c5f528c01bb5a2d)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-13931/13932", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Fri, 12 Apr 2024 09:21:01 GMT", "content-length": "13932"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/seman... (50c1720df09765c4)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false }), unsafe_: Metadata { final_url: "http://web-platform.test:8000/media/test... (1c5f528c01bb5a2d)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-13931/13932", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Fri, 12 Apr 2024 09:21:01 GMT", "content-length": "13932"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/seman... (50c1720df09765c4)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false } }))
 0:02.42 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.42 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:02.42 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.42 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.42 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] process_response_eof(Ok(ResourceFetchTiming { domain_lookup_start: 1712913661995633000, timing_check_passed: true, timing_type: Resource, redirect_count: 0, request_start: 1712913661995569000, secure_connection_start: 0, response_start: 0, fetch_start: 1712913661995548000, response_end: 1712913661997489000, redirect_start: 0, redirect_end: 0, connect_start: 41574315, connect_end: 41574315, start_time: 1712913661995548000 }))
 0:02.42 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:02.42 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event NeedData
 0:02.42 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Paused)
 0:02.42 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Paused)
 0:02.42 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Sending media session event playback state changed to Paused
 0:02.55 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event MetadataUpdated(Metadata { duration: None, width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (High Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.55 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event MetadataUpdated(Metadata { duration: Some(1.03s), width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (High Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.55 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event MetadataUpdated(Metadata { duration: None, width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (High Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.55 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveNothing to HaveMetadata
 0:02.55 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event MetadataUpdated(Metadata { duration: Some(1.03s), width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (High Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.55 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveMetadata to HaveMetadata
 0:02.55 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.55 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:02.55 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event SeekDone(0)
 0:02.55 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Paused)
 0:02.55 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event SeekDone(0)
 0:02.55 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Paused)
 0:02.55 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveMetadata to HaveEnoughData
 0:02.55 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Sending media session event playback state changed to Paused
 0:02.56 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.56 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:02.56 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event SeekDone(0)
 0:02.56 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event SeekDone(0)
 0:02.56 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Playing)
 0:02.56 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Playing)
 0:02.56 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Sending media session event playback state changed to Playing
 0:02.56 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.56 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.57 pid:33921 UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
 0:02.60 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.60 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.64 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.64 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.67 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.67 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.71 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.71 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.74 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.74 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.77 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.77 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.80 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.80 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.84 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.84 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.86 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.86 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.90 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.90 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.94 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.94 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:02.97 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:02.97 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.00 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.00 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.03 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.03 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.06 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event PositionChanged(0)
 0:03.06 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event PositionChanged(0)
 0:03.06 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Sending media session event set position state MediaPositionState { duration: 1.0, playback_rate: 1.0, position: 0.0 }
 0:03.07 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.07 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.11 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.11 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.14 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.14 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.17 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.17 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.21 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.21 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.23 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.23 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.27 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.27 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.30 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.30 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.33 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.33 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.36 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.36 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.40 pid:33921 [2024-04-12T09:21:02Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.40 pid:33921 [2024-04-12T09:21:02Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.43 pid:33921 [2024-04-12T09:21:03Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.43 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.46 pid:33921 [2024-04-12T09:21:03Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.46 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.50 pid:33921 [2024-04-12T09:21:03Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.50 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.53 pid:33921 [2024-04-12T09:21:03Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.53 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.57 pid:33921 [2024-04-12T09:21:03Z TRACE script::dom::htmlmediaelement] Player event VideoFrameUpdated
 0:03.57 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event VideoFrameUpdated
 0:03.57 pid:33921 [2024-04-12T09:21:03Z TRACE script::dom::htmlmediaelement] Player event PositionChanged(0)
 0:03.57 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event PositionChanged(0)
 0:03.57 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Sending media session event set position state MediaPositionState { duration: 1.0, playback_rate: 1.0, position: 0.0 }
 0:03.60 pid:33921 [2024-04-12T09:21:03Z TRACE script::dom::htmlmediaelement] Player event PositionChanged(1)
 0:03.60 pid:33921 [2024-04-12T09:21:03Z TRACE script::dom::htmlmediaelement] Player event EndOfStream
 0:03.60 pid:33921 [2024-04-12T09:21:03Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Stopped)
 0:03.60 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event PositionChanged(1)
 0:03.60 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Sending media session event set position state MediaPositionState { duration: 1.0, playback_rate: 1.0, position: 1.0 }
 0:03.60 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event EndOfStream
 0:03.60 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Stopped)
 0:03.60 pid:33921 [2024-04-12T09:21:03Z DEBUG script::dom::htmlmediaelement] Sending media session event playback state changed to None_
 0:03.63 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0
 0:03.63 INFO No more tests
 0:03.63 INFO No more tests
 0:03.63 INFO Closing logging queue
 0:03.63 INFO queue closed
 0:03.67 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 2 checks (1 subtests, 1 tests)
Expected results: 2
Unexpected results: 0
OK
 0:03.67 INFO Got 0 unexpected results, with 0 unexpected passes
 0:03.90 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:03.95 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:03.95 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:03.95 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:03.95 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:03.95 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:03.95 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:03.95 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:03.95 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:03.96 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:03.96 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:04.03 INFO Closing logging queue
 0:04.03 INFO queue closed


It seems there might be more to it than the ready state. Or am missing something?

@jdm
Copy link
Member Author

jdm commented Apr 12, 2024

Is there code that fires load events at track objects yet?

@jdm
Copy link
Member Author

jdm commented Apr 12, 2024

From reading the code, the test that is timing out may actually be making more progress than it used to, so it actually has a chance to time out because we never fire a load events at track objects.

@jdm
Copy link
Member Author

jdm commented Apr 12, 2024

Although that depends on whether the canplaythrough is actually being executed during the test.

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Apr 12, 2024

Is there code that fires load events at track objects yet?

That was one of the things I was looking for while trying to narrow down the origin of the timeout!

After frantically jumping around the code I ended up at HTMLElement and stopped digging further, thinking I must be on the wrong track having ended up at the most generic element.

A quick search for "load" gives me this:

~/dev/personal/servo/servo
% rg '"load"' -g **/*.rs -l
target/debug/build/servo_atoms-178e916273796c7d/out/atom.rs
target/debug/build/servo_atoms-4d68ad6eb5af7ed1/out/atom.rs
target/debug/build/servo_atoms-bf6da50e6e954bbd/out/atom.rs
target/debug/build/script-f0d303e4aa1fc7e9/out/Bindings/WebGPUBinding.rs
target/debug/build/servo_atoms-99d2e48d2d13c428/out/atom.rs
target/debug/build/script-c9c8665d9fb86b93/out/Bindings/WebGPUBinding.rs
target/debug/build/script-8af97b2a07ba57a3/out/Bindings/WebGPUBinding.rs
components/script/stylesheet_loader.rs
components/script/dom/htmliframeelement.rs
components/script/dom/htmlelement.rs
target/debug/build/script-5b89e9ad9f5df3ae/out/Bindings/WebGPUBinding.rs
components/script/dom/event.rs
components/script/dom/xmlhttprequest.rs
components/script/dom/document.rs
components/script/dom/htmlscriptelement.rs
components/script/dom/htmlimageelement.rs
components/script/dom/filereader.rs
components/script/dom/htmlstyleelement.rs

I am not sure what to make of this though. While I don't see any "track" modules listed, there might be some architectural indirection in the code that I am missing. I need to spend way more time in the code base to make an informed judgement.

From reading the code, the test that is timing out may actually be making more progress than it used to, so it actually has a chance to time out because we never fire a load events at track objects.

You have no idea how relieved I am reading this. It did not occur to me that some parts might simply be unimplemented. I was trying to relate my changes to the timout happening at track.onload and it slowly started to get to me that I couldn't find anything.

Although that depends on whether the canplaythrough is actually being executed during the test.

The canplaythrough callback is being executed.
I verified that by adding a log at the end of its body:

diff --git a/tests/wpt/tests/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html b/tests/wpt/tests/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
index 3ec47a39e2..a5f9c6938e 100644
--- a/tests/wpt/tests/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
+++ b/tests/wpt/tests/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
@@ -24,9 +24,11 @@ async_test(function(t) {
         assert_equals(track1.track.mode, 'disabled');
         assert_equals(track1.track.cues, null);
         track1.track.mode = 'hidden';
+        console.log("canplaythrough");
     }

..and checking the test output:

...
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Paused)
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveMetadata to HaveEnoughData
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Sending media session event playback state changed to Paused
 0:02.45 pid:23924 canplaythrough
...
Full output

RUST_LOG="script::dom::htmlmediaelement" ./mach test-wpt --headless html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html | tee track-mode-not-changed-by-new-track.log  
No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.16 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.16 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.16 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.17 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.17 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.17 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.17 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.17 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.17 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.17 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.18 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.18 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.18 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.18 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.18 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.18 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.39 SUITE_START: web-platform-test - running 1 tests
 0:01.39 INFO Using 1 child processes
 0:01.39 INFO Starting runner
 0:01.56 TEST_START: /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:01.56 WARNING Got command init_succeeded in state running
 0:02.33 pid:23924 Full command: /Users/palbrecht/dev/personal/servo/servo/target/debug/servo --hard-fail -u Servo/wptrunner --ignore-certificate-errors -z http://web-platform.test:8000/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html -Z replace-surrogates --user-stylesheet /Users/palbrecht/dev/personal/servo/servo/resources/ahem.css --certificate-path /Users/palbrecht/dev/personal/servo/servo/tests/wpt/tests/tools/certs/cacert.pem
pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] process_response(Ok(Filtered { filtered: Basic(Metadata { final_url: "http://web-platform.test:8000/media/test... (bc5326deb34eb564)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-192843/192844", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Fri, 12 Apr 2024 20:46:34 GMT", "content-length": "192844"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/seman... (d59f02baea450a95)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false }), unsafe_: Metadata { final_url: "http://web-platform.test:8000/media/test... (bc5326deb34eb564)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-192843/192844", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Fri, 12 Apr 2024 20:46:34 GMT", "content-length": "192844"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/seman... (d59f02baea450a95)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false } }))
 0:02.33 pid:23924 [2024-04-12T20:46:34Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.33 pid:23924 [2024-04-12T20:46:34Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] process_response_eof(Ok(ResourceFetchTiming { domain_lookup_start: 1712954794189127000, timing_check_passed: true, timing_type: Resource, redirect_count: 0, request_start: 1712954794189090000, secure_connection_start: 0, response_start: 0, fetch_start: 1712954794189076000, response_end: 1712954794190427000, redirect_start: 0, redirect_end: 0, connect_start: 59482967, connect_end: 59482967, start_time: 1712954794189076000 }))
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:02.33 pid:23924 [2024-04-12T20:46:34Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Paused)
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Handling player event NeedData
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Paused)
 0:02.33 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Sending media session event playback state changed to Paused
 0:02.44 pid:23924 [2024-04-12T20:46:34Z TRACE script::dom::htmlmediaelement] Player event MetadataUpdated(Metadata { duration: None, width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (Main Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.44 pid:23924 [2024-04-12T20:46:34Z TRACE script::dom::htmlmediaelement] Player event MetadataUpdated(Metadata { duration: Some(6.0272s), width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (Main Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.44 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Handling player event MetadataUpdated(Metadata { duration: None, width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (Main Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveNothing to HaveMetadata
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Handling player event MetadataUpdated(Metadata { duration: Some(6.0272s), width: 320, height: 240, format: "ISO MP4/M4A", is_seekable: true, video_tracks: ["H.264 (Main Profile)"], audio_tracks: ["MPEG-4 AAC"], is_live: false, title: None })
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveMetadata to HaveMetadata
 0:02.45 pid:23924 [2024-04-12T20:46:34Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:02.45 pid:23924 [2024-04-12T20:46:34Z TRACE script::dom::htmlmediaelement] Player event SeekDone(0)
 0:02.45 pid:23924 [2024-04-12T20:46:34Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Paused)
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Handling player event SeekDone(0)
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Paused)
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Changing ready state from HaveMetadata to HaveEnoughData
 0:02.45 pid:23924 [2024-04-12T20:46:34Z DEBUG script::dom::htmlmediaelement] Sending media session event playback state changed to Paused
 0:02.45 pid:23924 canplaythrough
 0:12.34 TEST_END: Test TIMEOUT, expected OK. Subtests passed 0/1. Unexpected 1
TIMEOUT A track appended after the initial track configuration does not change other tracks - Test timed outTIMEOUT /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:12.34 INFO No more tests
 0:12.34 INFO No more tests
 0:12.34 INFO Closing logging queue
 0:12.34 INFO queue closed
 0:12.37 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 2 checks (1 subtests, 1 tests)
Expected results: 0
Unexpected results: 2
  test: 1 (1 timeout)
  subtest: 1 (1 timeout)

Unexpected Results
------------------
/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
  TIMEOUT A track appended after the initial track configuration does not change other tracks - Test timed out
  TIMEOUT /html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html
 0:12.37 INFO Got 1 unexpected results, with 0 unexpected passes
 0:12.41 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:12.41 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:12.41 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:12.41 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:12.41 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:12.41 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:12.41 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:12.41 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:12.46 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:12.46 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:12.81 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:12.87 INFO Closing logging queue
 0:12.87 INFO queue closed

@jdm
Copy link
Member Author

jdm commented Apr 13, 2024

Nice! It definitely looks like the rest now fails because of unimplemented functionality rather than buggy functionality.

@jdm
Copy link
Member Author

jdm commented Apr 13, 2024

To be clear: I don't think we should try to bundle the work necessary to make that test pass with your existing changes. It's fine to update the expected result to a timeout.

@pylbrecht
Copy link
Sponsor Contributor

Nice! It definitely looks like the rest now fails because of unimplemented functionality rather than buggy functionality.

I might cry.

Then I will go through the failing tests and sort out which of these are timing out at a track.onload; I vaguely remember there are quite a few of these.

@pylbrecht
Copy link
Sponsor Contributor

Seems like only 2/10 tests are timing out at a track.onload:

/html/semantics/embedded-content/media-elements/track/track-element/track-cue-mutable-fragment.html
/html/semantics/embedded-content/media-elements/track/track-element/track-mode-not-changed-by-new-track.html

I will take a closer look at the others to see why they are timing out:

/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html
/html/canvas/element/manual/imagebitmap/createImageBitmap-invalid-args.html
/html/canvas/element/manual/imagebitmap/createImageBitmap-flipY.html
/html/canvas/element/manual/imagebitmap/createImageBitmap-drawImage.html
/fetch/range/non-matching-range-response.html
/css/selectors/media/media-playback-state.html

@pylbrecht
Copy link
Sponsor Contributor

Heartbeat: I am still investigating why these tests are timing out:

/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html
/html/canvas/element/manual/imagebitmap/createImageBitmap-invalid-args.html
/html/canvas/element/manual/imagebitmap/createImageBitmap-flipY.html
/html/canvas/element/manual/imagebitmap/createImageBitmap-drawImage.html
/fetch/range/non-matching-range-response.html
/css/selectors/media/media-playback-state.html

I don't have anything concrete enough to drop in a comment yet, but I am amassing investigative notes locally.
So far, all tests I had a closer look at are timing out while waiting on some event (play, canplay, canplaythrough) as part of their setup.

Why aren't these events fired? I don't know yet.
I need to drill into each test case one by one, which I am planning to do on Saturday when I have some kids-free hours.

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented Apr 21, 2024

62964bf fixes the unexpected TIMEOUTs of /css/selectors/media/media-playback-state.html locally. I triggered a WPT run to get the big picture.

For the canvas related test cases this nuance in the spec on ready states seems suspiciously relevant:

In practice, the difference between HAVE_METADATA and HAVE_CURRENT_DATA is negligible. Really the only time the difference is relevant is when painting a video element onto a canvas, where it distinguishes the case where something will be drawn (HAVE_CURRENT_DATA or greater) from the case where nothing is drawn (HAVE_METADATA or less).

Intriguing! I am going to give this a closer look in my next free time slot.

@pylbrecht
Copy link
Sponsor Contributor

Heartbeat: unfortunately I had to put in some extra hours at work, which means no progress on the Servo front.
Things should be a bit more relaxed on the weekend. 🤞

@pylbrecht
Copy link
Sponsor Contributor

Heartbeat: I started digging into these two canvas tests:

/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html

Both of them are stuck on awaiting video.play().

Looking at the received player events explains why:

 0:02.65 pid:65840 [2024-04-16T19:06:19Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.65 pid:65840 [2024-04-16T19:06:19Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:02.65 pid:65840 [2024-04-16T19:06:19Z TRACE script::dom::htmlmediaelement] Player event NeedData

We never even get to ReadyState::HaveMetadata; much less to any of ReadyState::HaveCurrentData, ReadyState::HaveFutureData, or ReadyState::HaveEnoughData.

We seem to fetch the entire media resource though:

 0:02.59 pid:65768 [2024-04-30T19:04:26Z DEBUG script::dom::htmlmediaelement] process_response(Ok(Filtered { filtered: Basic(Metadata { final_url: "http://web-platform.test:8000/html/canva... (ca5a15fec1c093ca)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-1599/1600", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Tue, 30 Apr 2024 19:04:26 GMT", "content-length": "1600"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/canva... (141743e45b9a6d51)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false }), unsafe_: Metadata { final_url: "http://web-platform.test:8000/html/canva... (ca5a15fec1c093ca)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-1599/1600", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Tue, 30 Apr 2024 19:04:26 GMT", "content-length": "1600"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/canva... (141743e45b9a6d51)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false } }))
 0:02.59 pid:65768 [2024-04-30T19:04:26Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.59 pid:65768 [2024-04-30T19:04:26Z DEBUG script::dom::htmlmediaelement] process_response_eof(Ok(ResourceFetchTiming { domain_lookup_start: 1714503866180324000, timing_check_passed: true, timing_type: Resource, redirect_count: 0, request_start: 1714503866180286000, secure_connection_start: 0, response_start: 0, fetch_start: 1714503866180269000, response_end: 1714503866182098000, redirect_start: 0, redirect_end: 0, connect_start: 64137385, connect_end: 64137385, start_time: 1714503866180269000 }))

So far I treated the player implementation in servo-media as a black box, which I don't need to change.
However, we cannot change the ready state to something other than ReadyState::HaveNothing when we only receive PlayerEvent::NeedData and PlayerEvent::StateChanged(Buffering), can we?
Could this be a hint that we need to dig into servo-media or am I entering an unnecessary rabbit hole here?

I tried the far fetched idea of "if the player is buffering, it could be paused on at least one available frame waiting for more data to ensure smooth playback". Setting the ready state to ReadyState::HaveCurrentData on PlayerEvent::StateChanged(Buffering) showed the same result: the test was stuck on await video.play() (and I bet video_size_preserved_after_ended.html would fail again, because we never wait for PlayerEvent::MetadataUpdated to be handled).


Full output of /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html

% RUST_LOG="script::dom::htmlmediaelement" ./mach test-wpt --headless /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.22 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.22 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.22 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.23 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.23 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.23 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.23 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.23 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.24 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.24 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.24 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.24 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.24 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.43 SUITE_START: web-platform-test - running 1 tests
 0:01.43 INFO Using 1 child processes
 0:01.43 INFO Starting runner
 0:01.60 TEST_START: /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:01.60 WARNING Got command init_succeeded in state running
 0:02.64 pid:65840 Full command: /Users/palbrecht/dev/personal/servo/servo/target/debug/servo --hard-fail -u Servo/wptrunner --ignore-certificate-errors -z http://web-platform.test:8000/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html -Z replace-surrogates --user-stylesheet /Users/palbrecht/dev/personal/servo/servo/resources/ahem.css --certificate-path /Users/palbrecht/dev/personal/servo/servo/tests/wpt/tests/tools/certs/cacert.pem
pid:65840 [2024-04-16T19:06:19Z DEBUG script::dom::htmlmediaelement] process_response(Ok(Filtered { filtered: Basic(Metadata { final_url: "http://web-platform.test:8000/html/canva... (ca5a15fec1c093ca)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-1599/1600", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Tue, 16 Apr 2024 19:06:19 GMT", "content-length": "1600"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/canva... (141743e45b9a6d51)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false }), unsafe_: Metadata { final_url: "http://web-platform.test:8000/html/canva... (ca5a15fec1c093ca)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-1599/1600", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Tue, 16 Apr 2024 19:06:19 GMT", "content-length": "1600"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/canva... (141743e45b9a6d51)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false } }))
 0:02.65 pid:65840 [2024-04-16T19:06:19Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.65 pid:65840 [2024-04-16T19:06:19Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:02.65 pid:65840 [2024-04-16T19:06:19Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.65 pid:65840 [2024-04-16T19:06:19Z DEBUG script::dom::htmlmediaelement] process_response_eof(Ok(ResourceFetchTiming { domain_lookup_start: 1713294379182951000, timing_check_passed: true, timing_type: Resource, redirect_count: 0, request_start: 1713294379182920000, secure_connection_start: 0, response_start: 0, fetch_start: 1713294379182902000, response_end: 1713294379184655000, redirect_start: 0, redirect_end: 0, connect_start: 122749634, connect_end: 122749634, start_time: 1713294379182902000 }))
 0:02.65 pid:65840 [2024-04-16T19:06:19Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:02.65 pid:65840 [2024-04-16T19:06:19Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:02.66 pid:65840 [2024-04-16T19:06:19Z DEBUG script::dom::htmlmediaelement] Handling player event NeedData
 0:02.66 pid:65840 [2024-04-16T19:06:19Z DEBUG script::dom::htmlmediaelement] Handling player event NeedData
 0:12.62 TEST_END: Test TIMEOUT, expected OK. Subtests passed 0/32. Unexpected 32
TIMEOUT sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=false - Test timed outNOTRUN sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=trueNOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=trueNOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=falseNOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=trueNOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=falseNOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=trueNOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=falseNOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=trueNOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=trueTIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:12.62 INFO No more tests
 0:12.62 INFO No more tests
 0:12.62 INFO Closing logging queue
 0:12.62 INFO queue closed
 0:12.66 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 33 checks (32 subtests, 1 tests)
Expected results: 0
Unexpected results: 33
  test: 1 (1 timeout)
  subtest: 32 (31 notrun, 1 timeout)

Unexpected Results
------------------
/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
  TIMEOUT sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=false - Test timed out
  NOTRUN sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=true
  NOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=false
  NOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=true
  TIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:12.66 INFO Got 1 unexpected results, with 0 unexpected passes
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:12.98 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:13.00 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:13.12 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:13.16 INFO Closing logging queue
 0:13.16 INFO queue closed

Full output of /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html

% RUST_LOG="script::dom::htmlmediaelement" ./mach test-wpt --headless /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html
No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.19 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.19 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.19 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.19 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.19 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.19 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.19 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.19 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.19 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.19 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.20 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.41 SUITE_START: web-platform-test - running 1 tests
 0:01.41 INFO Using 1 child processes
 0:01.41 INFO Starting runner
 0:01.58 TEST_START: /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html
 0:01.58 WARNING Got command init_succeeded in state running
 0:02.36 pid:66283 Full command: /Users/palbrecht/dev/personal/servo/servo/target/debug/servo --hard-fail -u Servo/wptrunner --ignore-certificate-errors -z http://web-platform.test:8000/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html -Z replace-surrogates --user-stylesheet /Users/palbrecht/dev/personal/servo/servo/resources/ahem.css --certificate-path /Users/palbrecht/dev/personal/servo/servo/tests/wpt/tests/tools/certs/cacert.pem
pid:66283 [2024-04-16T19:08:36Z DEBUG script::dom::htmlmediaelement] process_response(Ok(Filtered { filtered: Basic(Metadata { final_url: "http://web-platform.test:8000/html/canva... (ca5a15fec1c093ca)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-1599/1600", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Tue, 16 Apr 2024 19:08:36 GMT", "content-length": "1600"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/canva... (e343a2c232cf737e)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false }), unsafe_: Metadata { final_url: "http://web-platform.test:8000/html/canva... (ca5a15fec1c093ca)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-1599/1600", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Tue, 16 Apr 2024 19:08:36 GMT", "content-length": "1600"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/canva... (e343a2c232cf737e)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false } }))
 0:02.36 pid:66283 [2024-04-16T19:08:36Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:02.36 pid:66283 [2024-04-16T19:08:36Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:02.36 pid:66283 [2024-04-16T19:08:36Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.36 pid:66283 [2024-04-16T19:08:36Z DEBUG script::dom::htmlmediaelement] process_response_eof(Ok(ResourceFetchTiming { domain_lookup_start: 1713294516063812000, timing_check_passed: true, timing_type: Resource, redirect_count: 0, request_start: 1713294516063784000, secure_connection_start: 0, response_start: 0, fetch_start: 1713294516063761000, response_end: 1713294516065645000, redirect_start: 0, redirect_end: 0, connect_start: 122886514, connect_end: 122886514, start_time: 1713294516063761000 }))
 0:02.36 pid:66283 [2024-04-16T19:08:36Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:02.36 pid:66283 [2024-04-16T19:08:36Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:02.36 pid:66283 [2024-04-16T19:08:36Z DEBUG script::dom::htmlmediaelement] Handling player event NeedData
 0:02.36 pid:66283 [2024-04-16T19:08:36Z DEBUG script::dom::htmlmediaelement] Handling player event NeedData
 0:12.37 TEST_END: Test TIMEOUT, expected OK. Subtests passed 0/32. Unexpected 32
TIMEOUT sRGB-FF0100, Context srgb, ImageData srgb, cropSource=false - Test timed outNOTRUN sRGB-FF0100, Context srgb, ImageData srgb, cropSource=trueNOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, cropSource=falseNOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, cropSource=trueNOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, cropSource=falseNOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, cropSource=trueNOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, cropSource=falseNOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, cropSource=trueNOTRUN sRGB-BB0000, Context srgb, ImageData srgb, cropSource=falseNOTRUN sRGB-BB0000, Context srgb, ImageData srgb, cropSource=trueNOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, cropSource=falseNOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, cropSource=trueNOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, cropSource=falseNOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, cropSource=trueNOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, cropSource=falseNOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, cropSource=trueNOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, cropSource=falseNOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, cropSource=trueNOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, cropSource=falseNOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, cropSource=trueNOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, cropSource=falseNOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, cropSource=trueNOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, cropSource=falseNOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, cropSource=trueNOTRUN Rec2020-222000000, Context srgb, ImageData srgb, cropSource=falseNOTRUN Rec2020-222000000, Context srgb, ImageData srgb, cropSource=trueNOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, cropSource=falseNOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, cropSource=trueNOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, cropSource=falseNOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, cropSource=trueNOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, cropSource=falseNOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, cropSource=trueTIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html
 0:12.38 INFO No more tests
 0:12.38 INFO No more tests
 0:12.38 INFO Closing logging queue
 0:12.38 INFO queue closed
 0:12.41 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 33 checks (32 subtests, 1 tests)
Expected results: 0
Unexpected results: 33
  test: 1 (1 timeout)
  subtest: 32 (31 notrun, 1 timeout)

Unexpected Results
------------------
/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html
  TIMEOUT sRGB-FF0100, Context srgb, ImageData srgb, cropSource=false - Test timed out
  NOTRUN sRGB-FF0100, Context srgb, ImageData srgb, cropSource=true
  NOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, cropSource=false
  NOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, cropSource=true
  NOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, cropSource=false
  NOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, cropSource=true
  NOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, cropSource=false
  NOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, cropSource=true
  NOTRUN sRGB-BB0000, Context srgb, ImageData srgb, cropSource=false
  NOTRUN sRGB-BB0000, Context srgb, ImageData srgb, cropSource=true
  NOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, cropSource=false
  NOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, cropSource=true
  NOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, cropSource=false
  NOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, cropSource=true
  NOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, cropSource=false
  NOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, cropSource=true
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, cropSource=false
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, cropSource=true
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, cropSource=false
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, cropSource=true
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, cropSource=false
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, cropSource=true
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, cropSource=false
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, cropSource=true
  NOTRUN Rec2020-222000000, Context srgb, ImageData srgb, cropSource=false
  NOTRUN Rec2020-222000000, Context srgb, ImageData srgb, cropSource=true
  NOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, cropSource=false
  NOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, cropSource=true
  NOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, cropSource=false
  NOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, cropSource=true
  NOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, cropSource=false
  NOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, cropSource=true
  TIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-ImageBitmap-video.html
 0:12.41 INFO Got 1 unexpected results, with 0 unexpected passes
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:12.43 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:12.48 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:12.48 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:12.87 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:12.93 INFO Closing logging queue
 0:12.93 INFO queue closed

@gterzian
Copy link
Member

gterzian commented May 1, 2024

We never even get to ReadyState::HaveMetadata; much less to any of ReadyState::HaveCurrentData, ReadyState::HaveFutureData, or ReadyState::HaveEnoughData.

One thing I am thinking about, and looked a bit into just now, is that perhaps the player is not yet "ready" by the time we start interacting with it from the network listener(like pushing chunks of data).

It appears to me that setup needs to be called before any of the signals that send player events can be used.

Setup is called only when one of those methods on the player are called: https://github.com/servo/media/blob/45756bef67037ade0f4f0125d579fdc3f3d457c8/backends/gstreamer/player.rs#L789

Back in servo, when we do resource_fetch_algorithm, we first call self.setup_media_player, which creates the player, but it does not set it up. Then we immediately start fetching the resource.

So the player will only be setup once we start using it, for example at

.set_input_size(content_length)

So I don't know how the signalling works, see for example https://github.com/servo/media/blob/45756bef67037ade0f4f0125d579fdc3f3d457c8/backends/gstreamer/player.rs#L585

But I wouldn't be surprised is somehow we are missing some player events in some cases because of some interaction between the signal setup in setup and the rest. For example, perhaps calling connect_media_info_updated returns immediately, but it actually "takes some time" for the signal setup to be completed, and by the time it is, for short videos, we have already finished fetching all the data?

I have no proof for this, but the way of calling setup caught my attention.

The hypothesis could be tested by calling a method on the player, for example set_input_size, and doing this already near the top of resource_fetch_algorithm, and then sleeping for a bit of time before continuing to fetch the resource.

@gterzian
Copy link
Member

gterzian commented May 1, 2024

Also see this: https://github.com/servo/media/blob/45756bef67037ade0f4f0125d579fdc3f3d457c8/backends/gstreamer/player.rs#L692

// We block the caller of the setup method until we get
                                    // the first need-data signal, so we ensure that we
                                    // don't miss any data between the moment the client
                                    // calls setup and the player is actually ready to
                                    // get any data.

So there is already some synchronization, but perhaps not enough.

@pylbrecht
Copy link
Sponsor Contributor

@gterzian, thanks a lot for your input. That gave me some more missing pieces of the "how does this player thing work" puzzle.

I will start processing and digging most likely on the weekend.

@pylbrecht
Copy link
Sponsor Contributor

The hypothesis could be tested by calling a method on the player, for example set_input_size, and doing this already near the top of resource_fetch_algorithm, and then sleeping for a bit of time before continuing to fetch the resource.

I tried the following:

diff --git a/components/script/dom/htmlmediaelement.rs b/components/script/dom/htmlmediaelement.rs
index 8e1c255b20..797876a4bd 100644
--- a/components/script/dom/htmlmediaelement.rs
+++ b/components/script/dom/htmlmediaelement.rs
@@ -7,7 +7,7 @@ use std::collections::VecDeque;
 use std::rc::Rc;
 use std::sync::{Arc, Mutex};
 use std::time::{Duration, Instant};
-use std::{f64, mem};
+use std::{f64, mem, thread};
 
 use dom_struct::dom_struct;
 use embedder_traits::resources::{self, Resource as EmbedderResource};
@@ -917,6 +917,15 @@ impl HTMLMediaElement {
             self.queue_dedicated_media_source_failure_steps();
             return;
         }
+        self.player
+                .borrow()
+                .as_ref()
+                .unwrap()
+                .lock()
+                .unwrap()
+                .set_input_size(256).expect("boom");
+
+        thread::sleep(Duration::from_secs(5));
 
         // Steps 1-2.
         // Unapplicable, the `resource` variable already conveys which mode

However that still results in the same timeout.

Full output

% RUST_LOG="script::dom::htmlmediaelement" ./mach test-wpt --headless /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html

No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.18 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.19 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.19 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.19 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.19 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.19 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.19 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.19 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.19 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.19 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.19 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.19 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.41 SUITE_START: web-platform-test - running 1 tests
 0:01.41 INFO Using 1 child processes
 0:01.41 INFO Starting runner
 0:01.58 TEST_START: /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:01.58 WARNING Got command init_succeeded in state running
 0:09.88 pid:61344 Full command: /Users/palbrecht/dev/personal/servo/servo/target/debug/servo --hard-fail -u Servo/wptrunner --ignore-certificate-errors -z http://web-platform.test:8000/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html -Z replace-surrogates --user-stylesheet /Users/palbrecht/dev/personal/servo/servo/resources/ahem.css --certificate-path /Users/palbrecht/dev/personal/servo/servo/tests/wpt/tests/tools/certs/cacert.pem
pid:61344 [2024-05-05T18:20:58Z TRACE script::dom::htmlmediaelement] Player event StateChanged(Buffering)
 0:09.88 pid:61344 [2024-05-05T18:20:58Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:14.93 pid:61344 [2024-05-05T18:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event StateChanged(Buffering)
 0:14.93 pid:61344 [2024-05-05T18:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event NeedData
 0:14.93 pid:61344 [2024-05-05T18:21:03Z DEBUG script::dom::htmlmediaelement] process_response(Ok(Filtered { filtered: Basic(Metadata { final_url: "http://web-platform.test:8000/html/canva... (ca5a15fec1c093ca)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-1599/1600", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Sun, 05 May 2024 18:21:03 GMT", "content-length": "1600"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/canva... (141743e45b9a6d51)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false }), unsafe_: Metadata { final_url: "http://web-platform.test:8000/html/canva... (ca5a15fec1c093ca)", location_url: None, content_type: Some(ContentType("video/mp4")), charset: None, headers: Some({"content-type": "video/mp4", "content-range": "bytes 0-1599/1600", "server": "BaseHTTP/0.6 Python/3.11.5", "date": "Sun, 05 May 2024 18:21:03 GMT", "content-length": "1600"}), status: Some((206, [80, 97, 114, 116, 105, 97, 108, 32, 67, 111, 110, 116, 101, 110, 116])), https_state: None, referrer: Some("http://web-platform.test:8000/html/canva... (141743e45b9a6d51)"), referrer_policy: Some(NoReferrerWhenDowngrade), timing: None, redirected: false } }))
 0:14.93 pid:61344 [2024-05-05T18:21:03Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:14.93 pid:61344 [2024-05-05T18:21:03Z DEBUG script::dom::htmlmediaelement] process_response_eof(Ok(ResourceFetchTiming { domain_lookup_start: 1714933263143611000, timing_check_passed: true, timing_type: Resource, redirect_count: 0, request_start: 1714933263143219000, secure_connection_start: 0, response_start: 0, fetch_start: 1714933263142903000, response_end: 1714933263149937000, redirect_start: 0, redirect_end: 0, connect_start: 164196490, connect_end: 164196490, start_time: 1714933263142903000 }))
 0:14.93 pid:61344 [2024-05-05T18:21:03Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:14.93 pid:61344 [2024-05-05T18:21:03Z DEBUG script::dom::htmlmediaelement] Handling player event NeedData
 0:14.96 TEST_END: Test TIMEOUT, expected OK. Subtests passed 0/32. Unexpected 32
TIMEOUT sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=false - Test timed outNOTRUN sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=trueNOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=trueNOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=falseNOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=trueNOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=falseNOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=trueNOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=falseNOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=trueNOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=trueTIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:14.96 INFO No more tests
 0:14.96 INFO No more tests
 0:14.96 INFO Closing logging queue
 0:14.96 INFO queue closed
 0:15.00 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 33 checks (32 subtests, 1 tests)
Expected results: 0
Unexpected results: 33
  test: 1 (1 timeout)
  subtest: 32 (31 notrun, 1 timeout)

Unexpected Results
------------------
/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
  TIMEOUT sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=false - Test timed out
  NOTRUN sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=true
  NOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=false
  NOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=true
  TIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:15.00 INFO Got 1 unexpected results, with 0 unexpected passes
 0:15.39 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:15.43 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:15.43 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:15.43 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:15.43 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:15.43 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:15.43 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:15.43 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:15.43 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:15.49 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:15.49 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:15.53 INFO Closing logging queue
 0:15.53 INFO queue closed


I feel like diving into the GStreamer docs again. I am hoping to get a better understanding of how one needs to set up the player and how to interact with it.

@pylbrecht
Copy link
Sponsor Contributor

Reading the GStreamer did not help me too much.
My next idea was to sprinkle servo-media with some debug logs and it seems that setup() is never called. 👀

After patching Cargo.toml to use my local clone of servo-media:

diff --git a/Cargo.toml b/Cargo.toml
index 17f061f8cf..c2c3a9d498 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -91,9 +91,9 @@ selectors = { git = "https://github.com/servo/stylo", branch = "2023-09-01" }
 serde = "1.0.197"
 serde_bytes = "0.11"
 serde_json = "1.0"
-servo-media = { git = "https://github.com/servo/media" }
-servo-media-dummy = { git = "https://github.com/servo/media" }
-servo-media-gstreamer = { git = "https://github.com/servo/media" }
+servo-media = { path = "../media/servo-media" }
+servo-media-dummy = { path = "../media/backends/dummy" }
+servo-media-gstreamer = { path = "../media/backends/gstreamer" }
 servo_arc = { git = "https://github.com/servo/stylo", branch = "2023-09-01" }
 servo_atoms = { git = "https://github.com/servo/stylo", branch = "2023-09-01" }
 size_of_test = { git = "https://github.com/servo/stylo", branch = "2023-09-01" }

I added a debug!() on the top of setup():

diff --git a/backends/gstreamer/player.rs b/backends/gstreamer/player.rs
index 8f42906..04374b1 100644
--- a/backends/gstreamer/player.rs
+++ b/backends/gstreamer/player.rs
@@ -1,4 +1,5 @@
 use super::BACKEND_BASE_TIME;
+use log::debug;
 use crate::media_stream::GStreamerMediaStream;
 use crate::media_stream_source::{register_servo_media_stream_src, ServoMediaStreamSrc};
 use crate::render::GStreamerRender;
@@ -400,6 +401,7 @@ impl GStreamerPlayer {
     }
 
     fn setup(&self) -> Result<(), PlayerError> {
+        debug!("Setting up player");
         if self.inner.borrow().is_some() {
             return Ok(());
         }

and ran the test:

RUST_LOG="none,servo_media=debug" ./mach test-wpt --headless /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html

"Setting up player" was never logged.

Full output

No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.16 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.17 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.17 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.17 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.18 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.18 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.18 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.18 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.18 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.18 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.18 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.18 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.40 SUITE_START: web-platform-test - running 1 tests
 0:01.40 INFO Using 1 child processes
 0:01.40 INFO Starting runner
 0:01.55 TEST_START: /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:01.55 WARNING Got command init_succeeded in state running
 0:16.61 TEST_END: TIMEOUT, expected OK
 0:16.61 INFO No more tests
 0:16.61 INFO No more tests
 0:16.61 INFO Closing logging queue
 0:16.62 INFO queue closed
 0:16.67 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 1 checks (1 tests)
Expected results: 0
Unexpected results: 1
  test: 1 (1 timeout)

Unexpected Results
------------------
TIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:16.67 INFO Got 1 unexpected results, with 0 unexpected passes
 0:16.82 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:16.92 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:16.92 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:16.92 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:16.92 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:16.92 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:16.93 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:16.93 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:16.93 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:16.98 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:16.99 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:17.02 INFO Closing logging queue
 0:17.02 INFO queue closed


Then I thought "Is setup() really never called, or did I skrew up something with the logging?".

So I put a debug!() on top of GStreamerPlayer::new():

diff --git a/backends/gstreamer/player.rs b/backends/gstreamer/player.rs
index 8f42906..c1f7bc9 100644
--- a/backends/gstreamer/player.rs
+++ b/backends/gstreamer/player.rs
@@ -1,4 +1,5 @@
 use super::BACKEND_BASE_TIME;
+use log::debug;
 use crate::media_stream::GStreamerMediaStream;
 use crate::media_stream_source::{register_servo_media_stream_src, ServoMediaStreamSrc};
 use crate::render::GStreamerRender;
@@ -379,6 +380,7 @@ impl GStreamerPlayer {
         audio_renderer: Option<Arc<Mutex<dyn AudioRenderer>>>,
         gl_context: Box<dyn PlayerGLContext>,
     ) -> GStreamerPlayer {
+        debug!("Creating player with ID: {}", id);
         let _ = gst::DebugCategory::new(
             "servoplayer",
             gst::DebugColorFlags::empty(),

..and saw the log:

% RUST_LOG="none,servo_media=debug" ./mach test-wpt --headless /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html | tee lol.log
...
pid:82984 [2024-05-11T16:22:55Z DEBUG servo_media_gstreamer::player] Creating player with ID: 0
...
Full output

No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.22 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.22 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.23 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.23 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.23 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.24 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.24 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.24 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.25 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.44 SUITE_START: web-platform-test - running 1 tests
 0:01.44 INFO Using 1 child processes
 0:01.44 INFO Starting runner
 0:01.60 TEST_START: /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:01.60 WARNING Got command init_succeeded in state running
 0:14.49 pid:82984 Full command: /Users/palbrecht/dev/personal/servo/servo/target/debug/servo --hard-fail -u Servo/wptrunner --ignore-certificate-errors -z http://web-platform.test:8000/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html -Z replace-surrogates --user-stylesheet /Users/palbrecht/dev/personal/servo/servo/resources/ahem.css --certificate-path /Users/palbrecht/dev/personal/servo/servo/tests/wpt/tests/tools/certs/cacert.pem
pid:82984 [2024-05-11T16:22:55Z DEBUG servo_media_gstreamer::player] Creating player with ID: 0
 0:16.64 TEST_END: TIMEOUT, expected OK
 0:16.64 INFO No more tests
 0:16.64 INFO No more tests
 0:16.64 INFO Closing logging queue
 0:16.64 INFO queue closed
 0:16.67 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 1 checks (1 tests)
Expected results: 0
Unexpected results: 1
  test: 1 (1 timeout)

Unexpected Results
------------------
TIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:16.67 INFO Got 1 unexpected results, with 0 unexpected passes
 0:16.92 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:16.96 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:16.97 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:16.97 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:16.97 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:16.97 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:16.97 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:16.97 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:16.97 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:17.03 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:17.04 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:17.07 INFO Closing logging queue
 0:17.07 INFO queue closed

Does that really confirm that setup() is never called or am I missing something here?

@jdm
Copy link
Member Author

jdm commented May 11, 2024

I think your RUST_LOG may not be set up correctly. The one you need is servo_media_gstreamer=debug to print the log from the gstreamer backend crate.

@jdm
Copy link
Member Author

jdm commented May 11, 2024

Oh, wait, the second test shows that that's not an issue. Interesting. Looks like a compelling theory!

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented May 12, 2024

Oh wow. I forgot to run servo once before running the test to mitigate this MacOS issue: https://servo.zulipchat.com/#narrow/stream/263398-general/topic/WPT.20Tests.20on.20M1.20Mac/near/429070876

I just tried to run it again and now I see the "Setting up player" logs.

% RUST_LOG="none,servo_media_gstreamer=debug" ./mach test-wpt --headless /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
pid:66765 [2024-05-12T04:17:40Z DEBUG servo_media_gstreamer::player] Creating player with ID: 0
 0:07.63 pid:66765 [2024-05-12T04:17:45Z DEBUG servo_media_gstreamer::player] Setting up player
 0:07.63 pid:66765 [2024-05-12T04:17:45Z DEBUG servo_media_gstreamer::player] Setting up player
Full output

% RUST_LOG="none,servo_media_gstreamer=debug" ./mach test-wpt --headless /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
No build type specified so assuming `--dev`.
Running WPT tests with /Users/palbrecht/dev/personal/servo/servo/target/debug/servo
 0:01.20 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.20 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Create socket on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Bind on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.20 wptserve INFO Skip by failure: OSError(48, 'Address already in use')
 0:01.20 wptserve INFO Listen on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:01.21 wptserve INFO Starting http server on http://127.0.0.1:8003
 0:01.21 wptserve INFO Starting http server on http://127.0.0.1:8001
 0:01.21 wptserve INFO Starting http server on http://127.0.0.1:8000
 0:01.21 wptserve INFO Starting http server on http://127.0.0.1:8002
 0:01.21 wptserve INFO Starting https server on https://127.0.0.1:8444
 0:01.21 wptserve INFO Starting https server on https://127.0.0.1:8446
 0:01.21 wptserve INFO Starting https server on https://127.0.0.1:8445
 0:01.21 wptserve INFO Starting https server on https://127.0.0.1:8443
 0:01.21 wptserve INFO Starting http2 server on https://127.0.0.1:9000
 0:01.42 SUITE_START: web-platform-test - running 1 tests
 0:01.42 INFO Using 1 child processes
 0:01.42 INFO Starting runner
 0:01.58 TEST_START: /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:01.58 WARNING Got command init_succeeded in state running
 0:02.56 pid:66765 Full command: /Users/palbrecht/dev/personal/servo/servo/target/debug/servo --hard-fail -u Servo/wptrunner --ignore-certificate-errors -z http://web-platform.test:8000/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html -Z replace-surrogates --user-stylesheet /Users/palbrecht/dev/personal/servo/servo/resources/ahem.css --certificate-path /Users/palbrecht/dev/personal/servo/servo/tests/wpt/tests/tools/certs/cacert.pem
pid:66765 [2024-05-12T04:17:40Z DEBUG servo_media_gstreamer::player] Creating player with ID: 0
 0:07.63 pid:66765 [2024-05-12T04:17:45Z DEBUG servo_media_gstreamer::player] Setting up player
 0:07.63 pid:66765 [2024-05-12T04:17:45Z DEBUG servo_media_gstreamer::player] Setting up player
 0:12.58 TEST_END: Test TIMEOUT, expected OK. Subtests passed 0/32. Unexpected 32
TIMEOUT sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=false - Test timed outNOTRUN sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=trueNOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=trueNOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=falseNOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=trueNOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=falseNOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=trueNOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=falseNOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=trueNOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=trueNOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=falseNOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=trueNOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=falseNOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=trueTIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:12.58 INFO No more tests
 0:12.58 INFO No more tests
 0:12.59 INFO Closing logging queue
 0:12.59 INFO queue closed
 0:12.62 SUITE_END

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 33 checks (32 subtests, 1 tests)
Expected results: 0
Unexpected results: 33
  test: 1 (1 timeout)
  subtest: 32 (31 notrun, 1 timeout)

Unexpected Results
------------------
/html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
  TIMEOUT sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=false - Test timed out
  NOTRUN sRGB-FF0100, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-FF0100, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN sRGB-FF0100, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-FF0100, Context display-p3, ImageData display-p3, scaleImage=true
  NOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=false
  NOTRUN sRGB-BB0000, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-BB0000, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN sRGB-BB0000, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN sRGB-BB0000, Context display-p3, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-3FF000000, Context display-p3, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-222000000, Context srgb, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-222000000, Context srgb, ImageData display-p3, scaleImage=true
  NOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=false
  NOTRUN Rec2020-222000000, Context display-p3, ImageData srgb, scaleImage=true
  NOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=false
  NOTRUN Rec2020-222000000, Context display-p3, ImageData display-p3, scaleImage=true
  TIMEOUT /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html
 0:12.62 INFO Got 1 unexpected results, with 0 unexpected passes
 0:12.94 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:12.94 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:12.94 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:12.94 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:12.95 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:12.96 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:12.98 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:13.00 wptserve INFO Close on: (<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, '', '', '')
 0:13.08 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:13.12 INFO Closing logging queue
 0:13.12 INFO queue closed

It actually works with both RUST_LOG=none,servo_media=debug and RUST_LOG=none,servo_media_gstreamer=debug.

Apologies for the confusion. Now I'm all set to debug the player.

@pylbrecht
Copy link
Sponsor Contributor

Found another potential lead:

We are pushing data into the player. However the player keeps signalling that it needs data by emitting NeedData , even though we already reached process_response_eof().

...
 0:02.36 pid:66283 [2024-04-16T19:08:36Z TRACE script::dom::htmlmediaelement] Player event NeedData
 0:02.36 pid:66283 [2024-04-16T19:08:36Z DEBUG script::dom::htmlmediaelement] process_response_chunk()
 0:02.36 pid:66283 [2024-04-16T19:08:36Z DEBUG script::dom::htmlmediaelement] process_response_eof(Ok(ResourceFetchTiming { domain_lookup_start: 1713294516063812000, timing_check_passed: true, timing_type: Resource, redirect_count: 0, request_start: 1713294516063784000, secure_connection_start: 0, response_start: 0, fetch_start: 1713294516063761000, response_end: 1713294516065645000, redirect_start: 0, redirect_end: 0, connect_start: 122886514, connect_end: 122886514, start_time: 1713294516063761000 }))
 0:02.36 pid:66283 [2024-04-16T19:08:36Z TRACE script::dom::htmlmediaelement] Player event NeedData
...

This section from the GstAppSrc docs looks interesting in that regard:

When the application has finished pushing data into appsrc, it should call gst_app_src_end_of_stream or emit the end-of-stream action signal. After this call, no more buffers can be pushed into appsrc until a flushing seek occurs or the state of the appsrc has gone through READY.

We call end_of_stream(), but only under certain conditions (which I do not fully grasp, yet):

// If an error was previously received and no new fetch request was triggered,
// we skip processing the payload and notify the media backend that we are done
// pushing data.
if elem.generation_id.get() == self.generation_id {
if let Some(ref current_fetch_context) = *elem.current_fetch_context.borrow() {
if let Some(CancelReason::Error) = current_fetch_context.cancel_reason() {
if let Err(e) = elem
.player
.borrow()
.as_ref()
.unwrap()
.lock()
.unwrap()
.end_of_stream()
{
warn!("Could not signal EOS to player {:?}", e);
}
return;
}
}
}

@pylbrecht
Copy link
Sponsor Contributor

pylbrecht commented May 12, 2024

Neat, 062a0aa passes /html/canvas/element/manual/wide-gamut-canvas/canvas-display-p3-drawImage-video.html locally.
Let's see what ./mach try wpt has to say: https://github.com/pylbrecht/servo/actions/runs/9050730024 🤞

// edit:

This looks promising!
All unexpected results from #31415 (comment) except /fetch/range/non-matching-range-response.html are resolved. Now we got 9 different unexpected results, but quite a few unexpected PASSes.

I will go over the unexpected results to see how they relate to 062a0aa.

// edit 2:

Just to be sure that we have accurate results, I triggered another ./mach try wpt after rebasing on latest main: https://github.com/pylbrecht/servo/actions/runs/9053410162

// edit 3:

Two canvas tests are back with unexpected results:

ERROR [expected TIMEOUT] /html/canvas/element/manual/imagebitmap/createImageBitmap-drawImage.html
ERROR [expected TIMEOUT] /html/canvas/element/manual/imagebitmap/createImageBitmap-flipY.html

When I ran them locally, they sometimes pass and sometimes fail.
Also there is a new error message:

 0:02.50 pid:5067 [2024-05-13T04:17:59Z TRACE script::dom::htmlmediaelement] Player event Error("Error from element /GstPlayBin:playbin/GstURIDecodeBin:uridecodebin1/GstDecodeBin:decodebin1/avdec_h264:avdec_h264-1: Could not decode stream.\nNo valid frames decoded before end of stream\n../gst-libs/gst/video/gstvideodecoder.c(1421): gst_video_decoder_sink_event_default (): /GstPlayBin:playbin/GstURIDecodeBin:uridecodebin1/GstDecodeBin:decodebin1/avdec_h264:avdec_h264-1:\nno valid frames found")

I will keep digging.

@pylbrecht
Copy link
Sponsor Contributor

Heartbeat: as we had a major project release at work this week, I was quite busy with bugs-only-users-find-after-release.
I am expecting things to quiet down next week, which hopefully allows me to spend some time working on this issue.
Maybe I can even make some time for it this weekend 🤞

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants