[wpe-2.38] Sometimes progressive playback is not resumed after seek

[volodymyr-ogorodnik-red]

Sometimes in Euronews browser application (https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#app:com.metrological.app)
after seek forward or backward video playback is not resumed (remains paused). It will play normally when pressed OK or another seek operation.
Video is played using 'old' progressive path (not MSE).

Log analyzis shows that in wrong situation browser missed state transition to 'HaveCurrentData', and application can't resume playback after seek.

This happens because the gstreamer pipeline remains in state transition too long and can't process buffering events.

Normally it goes: seek -> Paused pipeline -> buffering (HaveCurrentData)-> finish_buffering(HaveEnoughData)->start_playback
In wrong situation, seek action takes too long (~2sec) to set PAUSED state on pipeline and we are missing the buffering(HaveCurrentData) stage. And player can't 'autoplay' the content after seek:

Aug 20 11:36:02.493125 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:58.728576576 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:560:doSeek: [Buffering] Pausing pipeline, resetting buffering level to 0 and forcing m_isBuffering true before seeking on stream mode
Aug 20 11:36:02.504100 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:58.732090539 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:571:doSeek: [Seek] Performing actual seek to 0:00:43.000000000 (endTime: 99:99:99.999999999) at rate 1.000000
Aug 20 11:36:02.567876 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:58.798885132 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:36:02.567876 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:58.798906280 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
.....
Aug 20 11:36:04.600837 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.836180575 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:36:04.600837 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.836205241 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2753:updateStates: [Buffering] Delaying m_isBuffering true --> false to force the proper change from not buffering to buffering when the async state change completes.
Aug 20 11:36:04.605119 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.836850945 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:36:04.605119 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.836871538 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:36:04.605119 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.836890760 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2753:updateStates: [Buffering] Delaying m_isBuffering true --> false to force the proper change from not buffering to buffering when the async state change completes.
Aug 20 11:36:04.661207 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.896937797 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:36:04.662154 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.896959130 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2647:updateStates: Pipeline State: PAUSED, old: PLAYING, pending: VOID_PENDING
Aug 20 11:36:04.662154 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.896976575 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2670:updateStates: [Buffering] m_isBuffering: true --> false
Aug 20 11:36:04.662154 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.896990945 16 0x12c18a0 INFO webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2673:updateStates: [Buffering] Complete.
Aug 20 11:36:04.662154 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.897010908 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2728:updateStates: Old state: PLAYING, new state: PAUSED (requested: VOID_PENDING)
Aug 20 11:36:04.662154 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.897030760 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2800:updateStates: Network State Changed from Loaded to Idle
Aug 20 11:36:04.663159 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.898643797 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Idle
Aug 20 11:36:04.663159 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.898667649 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2647:updateStates: Pipeline State: PAUSED, old: PLAYING, pending: VOID_PENDING
Aug 20 11:36:04.663159 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:02:00.898684945 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2670:updateStates: [Buffering] m_isBuffering: true --> false

In normal case transition takes much less time (~0.6sec) and finishes while buffering is still in progress.

Aug 20 11:35:57.828415 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.063707579 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:560:doSeek: [Buffering] Pausing pipeline, resetting buffering level to 0 and forcing m_isBuffering true before seeking on stream mode
Aug 20 11:35:57.842752 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.067710431 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:571:doSeek: [Seek] Performing actual seek to 0:00:50.000000000 (endTime: 99:99:99.999999999) at rate 1.000000
Aug 20 11:35:57.913713 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.145022171 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:57.913713 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.145045801 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.271704 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.409723616 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.271704 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.409764542 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.393565 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.470023616 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.393565 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.470093838 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.410528 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.471306208 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.410528 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.471342986 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.412773 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.472403430 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.412773 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.472429801 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.414982 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.542098727 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.414982 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.542119023 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.417510 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.542556430 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.417510 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.542574986 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.420533 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.602835171 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.420533 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.602862579 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.420533 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.602888023 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2753:updateStates: [Buffering] Delaying m_isBuffering true --> false to force the proper change from not buffering to buffering when the async state change completes.
Aug 20 11:35:58.420533 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.606769171 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.420533 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.606790504 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.420533 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.606811616 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2753:updateStates: [Buffering] Delaying m_isBuffering true --> false to force the proper change from not buffering to buffering when the async state change completes.
Aug 20 11:35:58.472845 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.666351319 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.472845 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.666380319 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.472845 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.666404097 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2753:updateStates: [Buffering] Delaying m_isBuffering true --> false to force the proper change from not buffering to buffering when the async state change completes.
Aug 20 11:35:58.495269 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.668825986 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.495269 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.668852356 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2747:updateStates: Async: State: PAUSED, pending: PAUSED
Aug 20 11:35:58.495269 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.668881912 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2753:updateStates: [Buffering] Delaying m_isBuffering true --> false to force the proper change from not buffering to buffering when the async state change completes.
Aug 20 11:35:58.553569 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.674883541 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveEnoughData, network=Loaded
Aug 20 11:35:58.556495 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.675530986 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2647:updateStates: Pipeline State: PAUSED, old: PLAYING, pending: VOID_PENDING
Aug 20 11:35:58.556495 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.675574578 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2670:updateStates: [Buffering] m_isBuffering: true --> true
Aug 20 11:35:58.556495 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.675594282 16 0x12c18a0 INFO webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2677:updateStates: [Buffering] still buffering, so HaveCurrentData.
Aug 20 11:35:58.556495 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.675674949 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2728:updateStates: Old state: PLAYING, new state: PAUSED (requested: VOID_PENDING)
Aug 20 11:35:58.556495 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.675716690 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2800:updateStates: Network State Changed from Loaded to Loading
Aug 20 11:35:58.556495 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.676233986 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2804:updateStates: Ready State Changed from HaveEnoughData to HaveCurrentData
Aug 20 11:35:58.559466 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.680867171 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2640:updateStates: Old States: ready=HaveCurrentData, network=Loading
Aug 20 11:35:58.559466 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.680892764 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2647:updateStates: Pipeline State: PAUSED, old: PLAYING, pending: VOID_PENDING
Aug 20 11:35:58.559466 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.680910727 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2670:updateStates: [Buffering] m_isBuffering: true --> true
Aug 20 11:35:58.559466 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.680926060 16 0x12c18a0 INFO webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2677:updateStates: [Buffering] still buffering, so HaveCurrentData.
Aug 20 11:35:58.559466 E0B7B1-APPSTB-301000193203 wpe.sh[15095]: 0:01:54.680946949 16 0x12c18a0 DEBUG webkitmediaplayer MediaPlayerPrivateGStreamer.cpp:2728:updateStates: Old state: PLAYING, new state: PAUSED (requested: VOID_PENDING)

Most likely this is scenario related to #1456 - without that fix the playback is not resumed in 100%.

The fact that gstreamer takes ~2s to change state from 'paused' to 'paused' is worth separate analyzis, probably specific to the platform.
Here I would appreciate any improvement to avoid loosing notification of ReadyState=HaveCurrentData, if this is possible in described scenario.

Thanks,
Vova.

[volodymyr-ogorodnik-red]

this change seem to be working for Euronews application without any regression in tests we did:

diff --git a/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp b/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp
index edfefc7422d9..186832d07a03 100644
--- a/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp
+++ b/Source/WebCore/platform/graphics/gstreamer/MediaPlayerPrivateGStreamer.cpp
@@ -2685,6 +2685,12 @@ void MediaPlayerPrivateGStreamer::updateStates()
     case GST_STATE_CHANGE_ASYNC:
         GST_DEBUG_OBJECT(pipeline(), "Async: State: %s, pending: %s", gst_element_state_get_name(m_currentState), gst_element_state_get_name(pending));
         // Change in progress.
+        if ((m_currentState == GST_STATE_PAUSED) && (m_isBuffering)) {
+           //Also if we are buffering, we could miss HaveCurrentData state if buffering finished before the transition complete.
+            GST_INFO_OBJECT(pipeline(), "Async: [Buffering] still buffering, so force HaveCurrentData.");
+            m_readyState = MediaPlayer::ReadyState::HaveCurrentData;
+            m_networkState = MediaPlayer::NetworkState::Loading;
+        }
 
         // Delay the m_isBuffering change by returning it to its previous value. Without this, the false --> true change
         // would go unnoticed by the code that should trigger a pause.

[eocanha]

The proposed change looks fine in principle. I've submitted it upstream for review and regression checking by the EWS bots as https://bugs.webkit.org/show_bug.cgi?id=300041 / WebKit/WebKit#51698.

[eocanha]

Patch landed upstream as https://commits.webkit.org/300933@main, backported to wpe-2.38 as ef2fbfe and to wpe-2.46 as ac4f27b. Closing Issue.