search

MythTV / mythtv

The official MythTV repository
https://www.mythtv.org
GNU General Public License v2.0
708 stars 346 forks source link

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

Closed ulmus-scott closed 2 years ago

ulmus-scott commented 2 years ago

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 https://github.com/MythTV/mythtv/commit/754d740d00455aaacbe7926520816dc72830b67e @gigem

gigem commented 2 years ago

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

ulmus-scott commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

The bad change https://github.com/MythTV/mythtv/commit/754d740d00455aaacbe7926520816dc72830b67e was reverted with additional breaking changes in https://github.com/MythTV/mythtv/commit/3f3ee474d803ea0e8f1e10bbc83eb45abf00635e .

See https://github.com/MythTV/mythtv/pull/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 commented 2 years ago

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)
ulmus-scott commented 2 years ago

This change is equivalent to the third alternative I gave in https://github.com/MythTV/mythtv/pull/512#issuecomment-1058770853 and only sometimes works.

I will continue investigating where more EOF code is needed.

Reopen this issue.

ulmus-scott commented 2 years ago

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 commented 2 years ago

@gigem if you want to keep MythPlayer::PrebufferEnoughFrames() as is see https://github.com/ulmus-scott/mythtv/commit/1a6022691e68f2ca5d36de98bb3b3723b6c23c86 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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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. https://github.com/MythTV/mythtv/commit/31126568be61528ed05eef04ca0bf7f0a3d4b004

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

Avoid premature playback exit for audio-only recordings. https://github.com/MythTV/mythtv/commit/cef316f803117339a3e954531aedd00b462a81e9

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

Guard against a null AudioOutput. https://github.com/MythTV/mythtv/commit/0aedcaef7a16b17712dfe6502cb2e6354e3b6f0c

Don't wait for paused audio to drain. Fixes #11730. https://github.com/MythTV/mythtv/commit/8b542e208d6a11c9d5d43a32a07ca8b82e9f2185

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

gigem commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

What frontend and video profile are you using?

ulmus-scott commented 2 years ago

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 commented 2 years ago

@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 https://github.com/MythTV/mythtv/pull/515 has merit, but it is no longer urgent.

gigem commented 2 years ago

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.