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

Regression: video hangs at end of file instead of exiting #511

Closed
ulmus-scott opened this issue Mar 3, 2022 · 18 comments
Closed

Regression: video hangs at end of file instead of exiting #511

ulmus-scott opened this issue Mar 3, 2022 · 18 comments
Assignees

Comments

@ulmus-scott
Copy link
Contributor

  • Platform: Xubuntu 21.10 Linux htpc 5.13.0-30-generic #33-Ubuntu SMP Fri Feb 4 17:03:31 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

  • MythTV version: v33/master

  • Package version: n/a

  • Component: mythfrontend

What steps will reproduce the bug?

Play a recording or video and let it play until the end of file.

How often does it reproduce? Is there a required condition?

Always.

What is the expected behaviour?

Playback exits.

What do you see instead?

Playback is paused at end of file. E decoding error End of file (-541478725) is shown in the log. Detecting EOF may be a solution.

Playback exits with Esc as expected or after pausing and playing the video (hitting space twice).

Additional information

git bisect yielded 754d740 @gigem

@gigem
Copy link
Contributor

gigem commented Mar 3, 2022

I can't reproduce this with either current master or current fixes/32. Both exit at the end of playback as expected.

@gigem gigem self-assigned this Mar 3, 2022
@ulmus-scott
Copy link
Contributor Author

In the frontend settings: Video -> Playback -> General Playback -> "Action on playback exit" is "exit without saving" and "prompt at end of recording" is unchecked.

On master I can trigger this every time. However, when making changes to the code to aid harmonizing mpegts-mythtv, in some instances it exited as expected, so this may be a race condition. (I am testing on a 2 core Intel Pentium G3258.)

From v32:
mythfrontend.20220303031531.66427.log
Note: "End of file" occurs only once the first time, but the second time I played that file I paused and then played at the end and now it appears three times.

A race condition is highly likely:
mythfrontend.20220303032300.66593.log
Exits the first time, but not the second for the same video file. Fails to exit a different recording.

Samples from https://code.mythtv.org/trac/ticket/13557 : file "a" was race-y, file "b" may also be race-y.

@bennettpeter
Copy link
Member

I tried this and I observe different behavior.

  1. My setting previously was "save and exit". That is no longer available and it showed that my setting was "2", which seems a bug - perhaps it should convert the setting?
  2. When setting "Exit without saving", it exited without saving as selected.
  3. When I selected "Always prompt(excluding Live TV)" but did not select "prompt at end of recording", it never prompted. Sometimes time it just exits at end sometimes it pauses at end. Perhaps the setting should be removed if it has no effect?

ulmus-scott added a commit to ulmus-scott/mythtv that referenced this issue Mar 3, 2022
@ulmus-scott
Copy link
Contributor Author

ulmus-scott commented Mar 3, 2022

The bad change 754d740 was reverted with additional breaking changes in 3f3ee47 .

See #512 for my fix.

logs with -v playback:debug
mythfrontend.20220303211243.9868.master.log
Note:
Only once per file played: Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file
Only after pausing and playing at EOF: CoreContext mythplayerui.cpp:256 (EventLoop) - HasReachedEof() at ...

mythfrontend.20220303210456.8601.mythplayer.log
Note:
Twice per file played: Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file
with this once in between: CoreContext mythplayerui.cpp:256 (EventLoop) - HasReachedEof() at ...

@gigem
Copy link
Contributor

gigem commented Mar 4, 2022

Scott, try this patch.

diff --git a/mythtv/libs/libmythtv/mythplayer.cpp b/mythtv/libs/libmythtv/mythplayer.cpp
index 8f7ac450c6..6a9f0738eb 100644
--- a/mythtv/libs/libmythtv/mythplayer.cpp
+++ b/mythtv/libs/libmythtv/mythplayer.cpp
@@ -833,15 +833,10 @@ bool MythPlayer::PrebufferEnoughFrames(int min_buffers)
         return false;
     }
 
-    // Make sure we have at least one frame available.  The EOF case
-    // can get here without one.
-    if (!m_videoOutput->ValidVideoFrames())
-        return false;
-
     if (!m_avSync.GetAVSyncAudioPause())
         m_audio.Pause(false);
     SetBuffering(false);
-    return true;
+    return m_videoOutput->ValidVideoFrames();
 }
 
 void MythPlayer::VideoEnd(void)

@gigem gigem closed this as completed in 4e35b3f Mar 4, 2022
gigem added a commit that referenced this issue Mar 4, 2022
Refs #511

(cherry picked from commit 4e35b3f)
@ulmus-scott
Copy link
Contributor Author

This change is equivalent to the third alternative I gave in #512 (comment) and only sometimes works.

I will continue investigating where more EOF code is needed.

Reopen this issue.

@ulmus-scott
Copy link
Contributor Author

The issue appears to be: TV::PlaybackLoop() is an infinite loop and repeatedly calls MythPlayerUI::VideoLoop() which calls MythPlayerUI::DisplayNormalFrame() which never progresses since it calls MythPlayer::PrebufferEnoughFrames() which gets stuck returning false when GetEof() returns kEofStateDelayed.

ulmus-scott added a commit to ulmus-scott/mythtv that referenced this issue Mar 4, 2022
@ulmus-scott
Copy link
Contributor Author

ulmus-scott commented Mar 4, 2022

@gigem if you want to keep MythPlayer::PrebufferEnoughFrames() as is see ulmus-scott@1a60226 for my new fix.

diff --git a/mythtv/libs/libmythtv/mythplayerui.cpp b/mythtv/libs/libmythtv/mythplayerui.cpp
index 7041fa996f..23480e7900 100644
--- a/mythtv/libs/libmythtv/mythplayerui.cpp
+++ b/mythtv/libs/libmythtv/mythplayerui.cpp
@@ -648,7 +648,8 @@ bool MythPlayerUI::DisplayNormalFrame(bool CheckPrebuffer)
     if (m_allPaused)
         return false;
 
-    if (CheckPrebuffer && !PrebufferEnoughFrames())
+    // ignore buffer at EOF to ensure playback loop exits
+    if (CheckPrebuffer && !PrebufferEnoughFrames() && GetEof() == kEofStateNone)
         return false;
 
     // clear the buffering state

@gigem
Copy link
Contributor

gigem commented Mar 4, 2022

I've already told you returning true in PrebufferEnoughFrames() when there are no valid frames is wrong. It causes invalid frames to be accessed. Bypassing the check in DisplayNormalFrame() is equally wrong. It is the eof of playback detection ELSEWHERE that is buggy. It was masked by the bug that allowed access of invalid frames. I will not reintroduce the invalid access bug to "fix" the end of playback bug.

Frankly, I don't see why PrebufferEnoughFrames() shouldn't wait normally for additional frames when near end of file has been reached. The only thing that should be different at near end of file is to not require extra frames be queued. Playback should end when the decoder signals end of file AND all frames have been played. I suggest you concentrate your efforts on finding and fixing that bug.

@gigem
Copy link
Contributor

gigem commented Mar 5, 2022

I belive at least part of the underlying problem has to do with frame counting. Bypassing the PrebufferingEnoughFrames() check and accessing invalid frames will incorrectly inflate the frames played count.

@ulmus-scott
Copy link
Contributor Author

While not usable as is, this appears to solve the problem:

diff --git a/mythtv/libs/libmythtv/mythplayerui.cpp b/mythtv/libs/libmythtv/mythplayerui.cpp
index 7041fa996f..16e45cabd4 100644
--- a/mythtv/libs/libmythtv/mythplayerui.cpp
+++ b/mythtv/libs/libmythtv/mythplayerui.cpp
@@ -241,7 +241,7 @@ void MythPlayerUI::EventLoop()
 
         bool videoDrained =
             m_videoOutput && m_videoOutput->ValidVideoFrames() < 1;
-        bool audioDrained =
+        bool audioDrained = true ||
             !m_audio.GetAudioOutput() ||
             m_audio.IsPaused() ||
             m_audio.GetAudioOutput()->GetAudioBufferedTime() < 100ms;

The audio lines appear to be for audio only recordings. I didn't know MythTV could make audio only recordings.

References:
Fixes #6974. Play all the way to the end of the video. 3112656

(last few seconds of video are not played) https://code.mythtv.org/trac/ticket/6974

Avoid premature playback exit for audio-only recordings. cef316f

(Position/duration of audio-only files is incorrect) https://code.mythtv.org/trac/ticket/11357

Guard against a null AudioOutput. 0aedcae

Don't wait for paused audio to drain. Fixes #11730. 8b542e2

(Playback doesn't exit at the end of playback) https://code.mythtv.org/trac/ticket/11730

@ulmus-scott ulmus-scott changed the title Regression: video pauses at end of file instead of exiting Regression: video hangs at end of file instead of exiting Mar 6, 2022
ulmus-scott added a commit to ulmus-scott/mythtv that referenced this issue Mar 6, 2022
I created an audio only TS and a video only TS from a sample and both
played until the end and exited correctly.

Fixes MythTV#511

For the audio only TS, MythTV appears to create black frames, which means I could not
actually test the "audio only" branch.
@gigem
Copy link
Contributor

gigem commented Mar 10, 2022

Scott, please try this patch. It's not necessarily the final fix but might help confirm what I think is happening.

diff --git a/mythtv/libs/libmythtv/mythplayerui.cpp b/mythtv/libs/libmythtv/mythplayerui.cpp
index 1edb662622..5b31683b14 100644
--- a/mythtv/libs/libmythtv/mythplayerui.cpp
+++ b/mythtv/libs/libmythtv/mythplayerui.cpp
@@ -244,7 +244,7 @@ void MythPlayerUI::EventLoop()
         }
 
         bool videoDrained =
-            m_videoOutput && m_videoOutput->ValidVideoFrames() < 1;
+            m_videoOutput && !m_videoOutput->EnoughDecodedFrames();
         bool audioDrained =
             !m_audio.GetAudioOutput() ||
             m_audio.IsPaused() ||

@ulmus-scott
Copy link
Contributor Author

David, no joy.

I took the liberty of adding some logging:

diff --git a/mythtv/libs/libmythtv/mythplayerui.cpp b/mythtv/libs/libmythtv/mythplayerui.cpp
index 7041fa996f..ef27ca8298 100644
--- a/mythtv/libs/libmythtv/mythplayerui.cpp
+++ b/mythtv/libs/libmythtv/mythplayerui.cpp
@@ -239,8 +239,18 @@ void MythPlayerUI::EventLoop()
             return;
         }
 
+        LOG(VB_PLAYBACK, LOG_ALERT, QString("HasReachedEof() with ValidVideoFrames() = %1, "
+                                            "EnoughDecodedFrames() = %2")
+                                    .arg(m_videoOutput->ValidVideoFrames())
+                                    .arg(m_videoOutput->EnoughDecodedFrames())
+           );
+        LOG(VB_PLAYBACK, LOG_ALERT, QString("HasReachedEof() with m_audio.IsPaused() = %1, "
+                                            "GetAudioBufferedTime() = %2 ms")
+                                    .arg(m_audio.IsPaused())
+                                    .arg(m_audio.GetAudioOutput()->GetAudioBufferedTime().count())
+           );
         bool videoDrained =
-            m_videoOutput && m_videoOutput->ValidVideoFrames() < 1;
+            m_videoOutput && !m_videoOutput->EnoughDecodedFrames();
         bool audioDrained =
             !m_audio.GetAudioOutput() ||
             m_audio.IsPaused() ||

Which gives an infinite stream of:

A  HasReachedEof() with ValidVideoFrames() = 0, EnoughDecodedFrames() = 0
A  HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 133 ms

Another, probably related bug is that the playback loop never exits, even after exiting the frontend, i.e. I had to Ctrl+C twice to kill it.

@ulmus-scott
Copy link
Contributor Author

The beginning of that infinite stream is:

2022-03-10 09:09:44.175393 E [5145/5208] Decoder decoders/avformatdecoder.cpp:4964 (GetFrame) - decoding error End of file (-541478725)
2022-03-10 09:09:44.207153 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 14, EnoughDecodedFrames() = 1
2022-03-10 09:09:44.207169 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 608 ms
2022-03-10 09:09:44.247098 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 13, EnoughDecodedFrames() = 1
2022-03-10 09:09:44.247118 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 568 ms
2022-03-10 09:09:44.287013 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 12, EnoughDecodedFrames() = 1
2022-03-10 09:09:44.287032 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 528 ms
2022-03-10 09:09:44.326994 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 11, EnoughDecodedFrames() = 1
2022-03-10 09:09:44.327012 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 488 ms
2022-03-10 09:09:44.367066 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 10, EnoughDecodedFrames() = 1
2022-03-10 09:09:44.367083 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 448 ms
2022-03-10 09:09:44.407174 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 9, EnoughDecodedFrames() = 1
2022-03-10 09:09:44.407190 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 408 ms
2022-03-10 09:09:44.447989 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 8, EnoughDecodedFrames() = 1
2022-03-10 09:09:44.448012 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 367 ms
2022-03-10 09:09:44.487284 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 7, EnoughDecodedFrames() = 0
2022-03-10 09:09:44.487311 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 328 ms
2022-03-10 09:09:44.527687 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 6, EnoughDecodedFrames() = 0
2022-03-10 09:09:44.527703 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 288 ms
2022-03-10 09:09:44.567336 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 5, EnoughDecodedFrames() = 0
2022-03-10 09:09:44.567351 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 248 ms
2022-03-10 09:09:44.607393 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 4, EnoughDecodedFrames() = 0
2022-03-10 09:09:44.607408 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 208 ms
2022-03-10 09:09:44.647494 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 3, EnoughDecodedFrames() = 0
2022-03-10 09:09:44.647514 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 168 ms
2022-03-10 09:09:44.687504 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 2, EnoughDecodedFrames() = 0
2022-03-10 09:09:44.687519 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 133 ms
2022-03-10 09:09:44.728054 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 1, EnoughDecodedFrames() = 0
2022-03-10 09:09:44.728070 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 133 ms
2022-03-10 09:09:44.767664 A [5145/5145] CoreContext mythplayerui.cpp:242 (EventLoop) - HasReachedEof() with ValidVideoFrames() = 0, EnoughDecodedFrames() = 0
2022-03-10 09:09:44.767687 A [5145/5145] CoreContext mythplayerui.cpp:247 (EventLoop) - HasReachedEof() with m_audio.IsPaused() = 0, GetAudioBufferedTime() = 133 ms

So ValidVideoFrames() is correct; the actual problem appears to be that the GetAudioBufferedTime() cutoff of < 100 ms is too short and, if MythTV had video frames, it won't synthesize black frames.

Which is why my fix to ignore the audio buffer for non-Music Choice streams worked.

@gigem
Copy link
Contributor

gigem commented Mar 10, 2022

What frontend and video profile are you using?

@ulmus-scott
Copy link
Contributor Author

mythfrontend
MythTV Version : v33-Pre-131-g1a9204f41e-dirty
OpenGL High Quality with
Decoder: Standard
Max CPUs: 2
Deblocking filter: yes
Video renderer: OpenGL
Video scaler: bicubic
Deinterlacers: high quality (neither OpenGL nor driver checked)

@ulmus-scott
Copy link
Contributor Author

@gigem I can no longer trigger this on master or fixes/32, so I will consider this "fixed".

It still hangs briefly (< 1 s) at the end of recordings, but exits normally otherwise.

I still think #515 has merit, but it is no longer urgent.

ulmus-scott added a commit to ulmus-scott/mythtv that referenced this issue Mar 10, 2022
I created an audio only TS and a video only TS from a sample and both
played until the end and exited correctly.

Fixes MythTV#511

For the audio only TS, MythTV appears to create black frames, which means I could not
actually test the "audio only" branch.
gigem pushed a commit that referenced this issue Mar 11, 2022
normal/video-only content.

Fixes #511

Signed-off-by: David Engel <dengel@mythtv.org>
gigem pushed a commit that referenced this issue Mar 11, 2022
normal/video-only content.

Refs #511

Signed-off-by: David Engel <dengel@mythtv.org>
(cherry picked from commit 3675395)
@gigem
Copy link
Contributor

gigem commented Mar 11, 2022

FYI, I still can't reliably reproduce the issue but your last, core fix looks reasonable enough and does't appear to do any harm. Thanks for being persistent.

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

Successfully merging a pull request may close this issue.

3 participants