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

MythMusic hangs after FFmpeg merge #686

Closed
kmdewaal opened this issue Dec 28, 2022 · 13 comments
Closed

MythMusic hangs after FFmpeg merge #686

kmdewaal opened this issue Dec 28, 2022 · 13 comments
Assignees
Labels
bug:hang-deadlock Hangs or deadlocks component:plugins Issues with plugins version:master Master Development Branch
Milestone

Comments

@kmdewaal
Copy link
Contributor

MythMusic hangs after starting to play music; it does not respond to key presses anymore and it the only way to stop it is to do a double Control-C. This happens when going from one track to the next or when MythMusic starts playing somewhere in a track.
This problem appeared after the latest FFmpeg merge.

  • Platform: Ubuntu 22.04.1, Fedora 37

  • MythTV version: v33-Pre

  • Package version: Built from source

  • Component: MythMusic

What steps will reproduce the bug?

Start mythfrontend
Select "Listen to Music"
This starts MythMusic playing music from the current playlist, in the current track.
When the track is played starting from the beginning it plays OK.
When the track starts playing from another position, e.g. somewhere in the middle, it hangs.
Terminate mythfrontend by doing a double Control-C or a "kill -9" from another terminal.
Start mythfrontend.
Select "Listen to Music"
This starts MythMusic playing music from the current playlist at the beginning of the current track.
This plays OK; let it play for e.g. 10 seconds.
Stop MythMusic by pressing Escape and do "Exit and stop playing music".
Select "Listen to Music"
This starts MythMusic playing music from the current playlist, in the current track at the last position, e.g. at 10 seconds.
This now again hangs forever.

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

100% reproducible.
It is possible that it depends on a configuration item; in my case MythMusic is configured to always continues where it was left, i.e. it starts to play from the current playlist, the current track at the last played position.

What is the expected behaviour?

Playing music from the last played position. It is like this in v32 and in v33-Pre before the FFmpeg merge.

What do you see instead?

Mythfrontend/MythMusic hangs.

Additional information

As MythMusic is OK in v32 and it fails in the current master (v33-Pre) I did a bisect and this ended here:

[klaas@modu mythtv]$ git bisect good
There are only 'skip'ped commits left to test.
The first bad commit could be any of:
163f468
71c34d7
ff32a77
67a442e
d8b7d3d
54902b0
a44bcfb
ad29e1c
c8bef3c
2cfd14e
422fbc8
40a04d5
e546928
71e2219
a1868de
753a94c
We cannot bisect more!

This set of commits is the commit that updates FFmpeg and all the commits to the MythTV sources that are needed to make it compile again. It is not possible to bisect further.

The correct behavior when playing back music is that at intervals a block of data is read and played etc.
In v32 that looks like this:

2022-12-27 20:12:16.656437 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:749:WriteStringListReal  MythSocket(3491790:99): write -> 99 50      QUERY_FILETRANSFER 76[]:[]REQUEST_BLOCK[]:[]131072
2022-12-27 20:12:16.661375 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:951:ReadStringListReal  MythSocket(3491790:99): read  <- 99 6       131072
2022-12-27 20:12:18.507719 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:749:WriteStringListReal  MythSocket(3491790:99): write -> 99 50      QUERY_FILETRANSFER 76[]:[]REQUEST_BLOCK[]:[]131072
2022-12-27 20:12:18.512373 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:951:ReadStringListReal  MythSocket(3491790:99): read  <- 99 6       131072
2022-12-27 20:12:20.357381 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:749:WriteStringListReal  MythSocket(3491790:99): write -> 99 50      QUERY_FILETRANSFER 76[]:[]REQUEST_BLOCK[]:[]131072
2022-12-27 20:12:20.361845 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:951:ReadStringListReal  MythSocket(3491790:99): read  <- 99 6       131072
2022-12-27 20:12:22.307034 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:749:WriteStringListReal  MythSocket(3491790:99): write -> 99 50      QUERY_FILETRANSFER 76[]:[]REQUEST_BLOCK[]:[]131072
2022-12-27 20:12:22.311751 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:951:ReadStringListReal  MythSocket(3491790:99): read  <- 99 6       131072
2022-12-27 20:12:24.086571 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:749:WriteStringListReal  MythSocket(3491790:99): write -> 99 50      QUERY_FILETRANSFER 76[]:[]REQUEST_BLOCK[]:[]131072
2022-12-27 20:12:24.090899 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:951:ReadStringListReal  MythSocket(3491790:99): read  <- 99 6       131072
2022-12-27 20:12:26.045824 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:749:WriteStringListReal  MythSocket(3491790:99): write -> 99 50      QUERY_FILETRANSFER 76[]:[]REQUEST_BLOCK[]:[]131072
2022-12-27 20:12:26.050414 I [166976/167121] MythSocketThread(-1) mythsocket.cpp:951:ReadStringListReal  MythSocket(3491790:99): read  <- 99 6       131072

This is from lines 1027-1038 in file mf-20221227-1835-music-ok-v32.log (attached).

This is the same sequence in v33-Pre and here the last log line is repeated forever while the GUI hangs:

2022-12-27 18:36:59.026568 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:744:WriteStringListReal  MythSocket(4026610:98): write -> 98 50      QUERY_FILETRANSFER 74[]:[]REQUEST_BLOCK[]:[]130047
2022-12-27 18:36:59.057033 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:946:ReadStringListReal  MythSocket(4026610:98): read  <- 98 1       0
2022-12-27 18:36:59.057105 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:744:WriteStringListReal  MythSocket(4026610:98): write -> 98 50      QUERY_FILETRANSFER 74[]:[]REQUEST_BLOCK[]:[]130047
2022-12-27 18:36:59.087706 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:946:ReadStringListReal  MythSocket(4026610:98): read  <- 98 1       0
2022-12-27 18:36:59.087900 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:744:WriteStringListReal  MythSocket(4026610:98): write -> 98 50      QUERY_FILETRANSFER 74[]:[]REQUEST_BLOCK[]:[]130047
2022-12-27 18:36:59.118764 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:946:ReadStringListReal  MythSocket(4026610:98): read  <- 98 1       0
2022-12-27 18:36:59.119027 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:744:WriteStringListReal  MythSocket(4026610:98): write -> 98 50      QUERY_FILETRANSFER 74[]:[]REQUEST_BLOCK[]:[]130047
2022-12-27 18:36:59.149791 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:946:ReadStringListReal  MythSocket(4026610:98): read  <- 98 1       0
2022-12-27 18:36:59.150045 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:744:WriteStringListReal  MythSocket(4026610:98): write -> 98 50      QUERY_FILETRANSFER 74[]:[]REQUEST_BLOCK[]:[]130047
2022-12-27 18:36:59.180596 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:946:ReadStringListReal  MythSocket(4026610:98): read  <- 98 1       0
2022-12-27 18:36:59.180722 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:744:WriteStringListReal  MythSocket(4026610:98): write -> 98 50      QUERY_FILETRANSFER 74[]:[]REQUEST_BLOCK[]:[]130047
2022-12-27 18:36:59.211158 I [164036/164186] MythSocketThread(-1) mythsocket.cpp:946:ReadStringListReal  MythSocket(4026610:98): read  <- 98 1       0

This is from lines 1011-1022 in file mf-20221227-1835-music-fail.log (attached).

I did have a look at the commits that make up the FFmeg merge but I did not see anything obviously wrong.

This is the log file for v33-Pre where MythMusic fails:
mf-20221227-1835-music-fail.log

And this is the log file for v32 where MythMusic plays OK:
mf-20221227-1835-music-ok-v32.log

@kmdewaal kmdewaal added version:master Master Development Branch bug:hang-deadlock Hangs or deadlocks component:plugins Issues with plugins labels Dec 28, 2022
@kmdewaal kmdewaal added this to the 33.0 milestone Dec 28, 2022
@Jpilk
Copy link

Jpilk commented Dec 29, 2022

Hi Klaas: I don't use MythMusic a lot, mainly because the in-play controls have seemed not to give the results I expected; but maybe I misunderstood. Highlighting the FF ikon and repeatedly pressing Enter doesn't skip forward cleanly. But with my settings I'm not getting hangups. F36/master.

Mostly, for audio, I select track and player from the file manager. They are mainly mp2 with an .mp3 file extension.

@paul-h
Copy link
Contributor

paul-h commented Dec 29, 2022

@Jpilk If I'm understanding what @kmdewaal is saying you will only see the issue if you have the Resume mode (playlist) setting set to Exact which causes a seek when resuming playback in the Music plugin.

@kmdewaal
Copy link
Contributor Author

@paul-h yes it is the seek that gives the problem. Starting playback from the start is OK but then manually skipping forward (5 seconds in my system) also causes a hang.

I did some more testing today after @Jpilk reported it works OK for him.

My main music collection is on a NAS and is mounted on the MythTV box with NFS. I have had this setup, with the NAS storing the music and the videos, for many years and it has always worked OK.
Now, after the FFmpeg merge, playing a track from there gives the problem.

BUT... Today I did test with a smaller music collection stored on a local hard drive and this plays OK, both for seek when resuming playback and for skipping forward.

@kmdewaal kmdewaal self-assigned this Feb 5, 2023
@ijc
Copy link
Contributor

ijc commented Feb 19, 2023

I seeing this since upgrading to v33 as well -- things hang at the end of a track instead of progressing to the next track. The "resume mode" doesn't seem to make any difference in my case.

But perhaps most interestingly my music is also on NFS.

@ijc
Copy link
Contributor

ijc commented Feb 19, 2023

I captured some stack traces while mbe was wedged in this state (bt.log). I guess the interesting threads might be:

  • Thread 45 (Thread 0x7f7353fe76c0 (LWP 29251) "RingBuffer"): Blocked in a futex wait
  • Thread 44 (Thread 0x7f735aff56c0 (LWP 29250) "MythSocketThrea"), Thread 43 (Thread 0x7f74b8bfd6c0 (LWP 29248) "MythSocketThrea"), Thread 41 (Thread 0x7f735cff96c0 (LWP 26598) "MythSocketThrea"), Thread 40 (Thread 0x7f73537e66c0 (LWP 26594) "MythSocketThrea")`, all of which are blocked in the same poll:
#0  0x00007f74c851b0af in __GI___poll (fds=0x7f739c001f40, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f74c3a189ae in g_main_context_poll (priority=<optimized out>, n_fds=2, fds=0x7f739c001f40, timeout=<optimized out>, context=0x7f739c004130) at ../../../glib/gmain.c:4553
#2  g_main_context_iterate (context=context@entry=0x7f739c004130, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../../../glib/gmain.c:4243
#3  0x00007f74c3a18acc in g_main_context_iteration (context=0x7f739c004130, may_block=1) at ../../../glib/gmain.c:4313
#4  0x00007f74c890984e in QEventDispatcherGlib::processEvents (this=0x7f739c0008e0, flags=...) at kernel/qeventdispatcher_glib.cpp:425
#5  0x00007f74c88b017b in QEventLoop::exec (this=this@entry=0x7f735cff89b0, flags=..., flags@entry=...) at ../../include/QtCore/../../src/corelib/global/qflags.h:69
#6  0x00007f74c86cab87 in QThread::exec (this=<optimized out>) at ../../include/QtCore/../../src/corelib/global/qflags.h:121
#7  0x00007f74c9c8e741 in ?? () from /lib/x86_64-linux-gnu/libmythbase-33.so.33
#8  0x00007f74c86cbd43 in QThreadPrivate::start (arg=0x557d945804f0) at thread/qthread_unix.cpp:331
#9  0x00007f74c84a7fd4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#10 0x00007f74c852866c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Maybe there is something broken with polling on an NFS fd either generally or specifically in Qt's use?

@Jpilk
Copy link

Jpilk commented Feb 20, 2023

I still haven't reproduced a hangup in either 32/fixes or master, but I ought to clarify my comment of 29 Dec. Stepping forward during playback is fine for single steps, but multiple steps in quick succession confuse the ringbuffer, and playback continues with short out-of-order segments. Usually it eventually recovers. Since most of my 'songs' are much longer than 3 minutes this makes seeking tedious and I usually use smplayer or mpv.

Single steps give FE log messages like "avfdecoder.o: seek time 6273", where the number is in seconds from start-of-file and the usual increment is 5s. Holding down the spacebar for some time gives "AOBase: Buffer is full, AddData returning false" followed by tens of seconds of choppy repetitive playback, eventually becoming ok. I suspect that a 'lock until buffer update is complete' might help...

I haven't noticed any difference in this between local storage and NAS using cifs, but obviously the time to complete is likely to be different in each case.

HTH, John

@ijc
Copy link
Contributor

ijc commented Mar 12, 2023

With -V playback:debug on the frontend the last messages I see before the hang are:

2023-03-12T10:06:46.849815+00:00 iranon mythfrontend: mythfrontend[443928]: I CoreContext remoteavformatcontext.h:82 (Open) RemoteAVFormatContext::Open: probed file as flac
2023-03-12T10:06:46.849849+00:00 iranon mythfrontend: mythfrontend[443928]: I avfDecoder avfdecoder.cpp:453 (run) avfdecoder.o: seek time 4
2023-03-12T10:07:27.506198+00:00 iranon mythfrontend: mythfrontend[443928]: I CoreContext decoderhandler.cpp:177 (stop) DecoderHandler: Stopping decoder

The first is from https://github.com/MythTV/mythtv/blob/master/mythplugins/mythmusic/mythmusic/avfdecoder.cpp#L453 and if I attach gdb to my hung mfe then I get:

Thread 35 (Thread 0x7f9dc957a6c0 (LWP 444133) "avfDecoder"):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f9f45acdd9b in QtLinuxFutex::_q_futex (val3=0, addr2=0x0, val2=0, val=<optimized out>, op=0, addr=<optimized out>) at thread/qfutex_p.h:116
#2  QtLinuxFutex::futexWait<QBasicAtomicInteger<unsigned int> > (expectedValue=<optimized out>, futex=...) at thread/qfutex_p.h:135
#3  futexSemaphoreTryAcquire_loop<false> (timeout=-1, nn=8589934593, curValue=<optimized out>, u=...) at thread/qsemaphore.cpp:219
#4  futexSemaphoreTryAcquire<false> (timeout=-1, n=n@entry=1, u=...) at thread/qsemaphore.cpp:262
#5  QSemaphore::acquire (this=this@entry=0x7f9dc9578d90, n=n@entry=1) at thread/qsemaphore.cpp:326
#6  0x00007f9f45cbc78f in QMetaMethod::invoke (this=<optimized out>, object=0x564d388fc1f0, connectionType=Qt::BlockingQueuedConnection, returnValue=..., val0=..., val1=..., val2=..., val3=..., val4=..., val5=..., val6=..., val7=..., val8=..., val9=...) at kernel/qmetaobject.cpp:2358
#7  0x00007f9f45cc1726 in QMetaObject::invokeMethod (obj=0x564d388fc1f0, member=0x7f9f4b26f2c9 "ReadReal", type=Qt::BlockingQueuedConnection, ret=..., val0=..., val1=..., val2=..., val3=..., val4=..., val5=..., val6=..., val7=..., val8=..., val9=...) at kernel/qmetaobject.cpp:1522
#8  0x00007f9f4b093b38 in MythSocket::Read(char*, int, std::chrono::duration<long, std::ratio<1l, 1000l> >) () from /lib/x86_64-linux-gnu/libmythbase-33.so.33
#9  0x00007f9f4b0cb4d5 in RemoteFile::Read(void*, int) () from /lib/x86_64-linux-gnu/libmythbase-33.so.33
#10 0x00007f9f45268f89 in ?? () from /lib/x86_64-linux-gnu/libmythavformat.so.59
#11 0x00007f9f4526afb0 in avio_read_partial () from /lib/x86_64-linux-gnu/libmythavformat.so.59
#12 0x00007f9f45375726 in ?? () from /lib/x86_64-linux-gnu/libmythavformat.so.59
#13 0x00007f9f4529d023 in ?? () from /lib/x86_64-linux-gnu/libmythavformat.so.59
#14 0x00007f9f453a97b6 in ?? () from /lib/x86_64-linux-gnu/libmythavformat.so.59
#15 0x00007f9f453a9fc4 in ?? () from /lib/x86_64-linux-gnu/libmythavformat.so.59
#16 0x00007f9f453aa315 in ?? () from /lib/x86_64-linux-gnu/libmythavformat.so.59
#17 0x00007f9f453aaa1f in av_seek_frame () from /lib/x86_64-linux-gnu/libmythavformat.so.59
#18 0x00007f9e356b807e in ?? () from /usr/lib/x86_64-linux-gnu/mythtv/plugins/libmythmusic.so
#19 0x00007f9f45acbd43 in QThreadPrivate::start (arg=0x564d3af33300) at thread/qthread_unix.cpp:331
#20 0x00007f9f458a7fd4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#21 0x00007f9f4592866c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Full logs: mfe-bt.txt

This corresponds to:

            if (av_seek_frame(m_inputContext->getContext(), -1,
                              (int64_t)(m_seekTime * AV_TIME_BASE), 0) < 0)
                LOG(VB_GENERAL, LOG_ERR, "Error seeking");

Looking at another call in mythtv/libs/libmythtv/decoders/avformatdecoder.cpp I see:

    // convert framenumber to normalized timestamp
    long double seekts = desiredFrame * AV_TIME_BASE / m_fps;
    ts += (long long)seekts;

    // XXX figure out how to do snapping in this case
    bool exactseeks = DecoderBase::GetSeekSnap() == 0U;

    int flags = (m_doRewind || exactseeks) ? AVSEEK_FLAG_BACKWARD : 0;

    if (av_seek_frame(m_ic, -1, ts, flags) < 0)

I wonder if that / m_fps is relevant? Also ts here is a long long while m_seekTime in the mythmusic case is a double.

I can't see that anything changed on the ffmpeg side wrt the arguments to av_seek_frame though so not sure why it would regress, maybe I'm barking up completely the wrong tree...

Could this be at all related to the issues with videochannels which have a static graphic (low or zero framerate) which had various problems at one point (something to do with audio vs video as the time base?)? A music stream is superficially a bit similar to that case perhaps?

@ijc
Copy link
Contributor

ijc commented Mar 12, 2023

With debug symbols for libavcodec:

#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f7aaa8cdd9b in QtLinuxFutex::_q_futex (val3=0, addr2=0x0, val2=0, val=<optimized out>, op=0, addr=<optimized out>)
    at thread/qfutex_p.h:116
#2  QtLinuxFutex::futexWait<QBasicAtomicInteger<unsigned int> > (expectedValue=<optimized out>, futex=...) at thread/qfutex_p.h:135
#3  futexSemaphoreTryAcquire_loop<false> (timeout=-1, nn=8589934593, curValue=<optimized out>, u=...) at thread/qsemaphore.cpp:219
#4  futexSemaphoreTryAcquire<false> (timeout=-1, n=n@entry=1, u=...) at thread/qsemaphore.cpp:262
#5  QSemaphore::acquire (this=this@entry=0x7f795931fd90, n=n@entry=1) at thread/qsemaphore.cpp:326
#6  0x00007f7aaaabc78f in QMetaMethod::invoke (this=<optimized out>, object=0x55c17ecccc20, connectionType=Qt::BlockingQueuedConnection, 
    returnValue=..., val0=..., val1=..., val2=..., val3=..., val4=..., val5=..., val6=..., val7=..., val8=..., val9=...)
    at kernel/qmetaobject.cpp:2358
#7  0x00007f7aaaac1726 in QMetaObject::invokeMethod (obj=0x55c17ecccc20, member=0x7f7ab026f2c9 "ReadReal", type=Qt::BlockingQueuedConnection, 
    ret=..., val0=..., val1=..., val2=..., val3=..., val4=..., val5=..., val6=..., val7=..., val8=..., val9=...) at kernel/qmetaobject.cpp:1522
#8  0x00007f7ab0093b38 in MythSocket::Read(char*, int, std::chrono::duration<long, std::ratio<1l, 1000l> >) ()
   from /lib/x86_64-linux-gnu/libmythbase-33.so.33
#9  0x00007f7ab00cb4d5 in RemoteFile::Read(void*, int) () from /lib/x86_64-linux-gnu/libmythbase-33.so.33
#10 0x00007f7aaa068f89 in read_packet_wrapper (size=<optimized out>, buf=0x55c17ed72a41 "TRACKS=99\021", s=0x55c17ecca780)
    at libavformat/aviobuf.c:533
#11 fill_buffer (s=0x55c17ecca780) at libavformat/aviobuf.c:577
#12 0x00007f7aaa06afb0 in avio_read_partial (s=0x55c17ecca780, buf=0x7f7950001390 "\220\004", size=size@entry=1024) at libavformat/aviobuf.c:729
#13 0x00007f7aaa175726 in ff_raw_read_partial_packet (s=s@entry=0x55c17eccc280, pkt=pkt@entry=0x55c17eccc680) at libavformat/rawdec.c:48
#14 0x00007f7aaa09d023 in flac_read_timestamp (s=s@entry=0x55c17eccc280, stream_index=stream_index@entry=0, ppos=ppos@entry=0x7f79593205f8, 
    pos_limit=pos_limit@entry=37671290) at libavformat/flacdec.c:281
#15 0x00007f7aaa1a97b6 in read_timestamp (
    read_timestamp={int64_t (int64_t (*)(struct AVFormatContext *, int, int64_t *, int64_t), int64_t, int64_t *, int, AVFormatContext *)} 0x7f7aaa1a9679 <ff_find_last_ts+121>, pos_limit=<optimized out>, ppos=0x7f79593205f8, stream_index=0, s=0x55c17eccc280) at libavformat/seek.c:277
#16 ff_find_last_ts (s=s@entry=0x55c17eccc280, stream_index=stream_index@entry=0, ts=ts@entry=0x7f7959320808, pos=pos@entry=0x7f79593206b0, 
    read_timestamp_func=read_timestamp_func@entry=0x7f7aaa09cf90 <flac_read_timestamp>) at libavformat/seek.c:363
#17 0x00007f7aaa1a9fc4 in ff_gen_search (s=s@entry=0x55c17eccc280, stream_index=stream_index@entry=0, target_ts=target_ts@entry=88200, 
    pos_min=<optimized out>, pos_min@entry=0, pos_max=<optimized out>, pos_limit=pos_limit@entry=-1, ts_min=0, ts_max=<optimized out>, flags=0, 
    ts_ret=0x7f7959320868, read_timestamp_func=0x7f7aaa09cf90 <flac_read_timestamp>) at libavformat/seek.c:419
#18 0x00007f7aaa1aa315 in ff_seek_frame_binary (s=s@entry=0x55c17eccc280, stream_index=stream_index@entry=0, target_ts=target_ts@entry=88200, 
    flags=flags@entry=0) at libavformat/seek.c:338
#19 0x00007f7aaa1aaa1f in seek_frame_internal (flags=0, timestamp=88200, stream_index=0, s=0x55c17eccc280) at libavformat/seek.c:626
#20 av_seek_frame (s=0x55c17eccc280, stream_index=<optimized out>, timestamp=<optimized out>, flags=0) at libavformat/seek.c:649
#21 0x00007f7990edb07e in ?? () from /usr/lib/x86_64-linux-gnu/mythtv/plugins/libmythmusic.so
#22 0x00007f7aaa8cbd43 in QThreadPrivate::start (arg=0x55c17e4283b0) at thread/qthread_unix.cpp:331
#23 0x00007f7aaa6a7fd4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#24 0x00007f7aaa72866c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

It seems that flac_read_timestamp is stuck in an infinite loop due to size == 0 and ret >= 0 (ret is optimised out so I can't see the value, but it's not matching ret < 0 AFAICT so we keep going round the for(;;) loop).

https://stackoverflow.com/questions/17765667/flac-seeking-with-ffmpeg seems similar but is nearly a decade old so I think probably not relevant

@kmdewaal
Copy link
Contributor Author

Thanks for the tracebacks and the analysis. It is not a trivial problem. What has changed is the FFmpeg version and the process of gluing MythTV and FFmpeg has been done with great enthusiasm but with little respect for the code...
On the other hand, this looks like a decoder that refuses to stop and that is something that happens a lot with playing DVB audio channels with live TV, for already a long time.
It looks like this needs to be fixed in the hardest possible way and that is by understanding how the whole thing works....
To be continued.

@kmdewaal
Copy link
Contributor Author

Lots of testing today showed that my idea about the problem being related to music stored on NFS is not correct.
The "MythMusic hangs" happens at the moment not with mp3 files but only with flac files. The mp3 files play correct from local storage and from NFS. The flac files fail in the manner described when played from local storage and from NFS.
This corresponds with the backtrace provided by @ijc which also shows an issue in flac.
To be continued.

@kmdewaal
Copy link
Contributor Author

The problem is caused by how the end-of-file is handled. In MythMusic the decoding is done by FFmpeg but the file I/O is done by MythTV. The version of FFmpeg that is in fixes/32 still has temporary code that converts a read value of 0 bytes into an EOF status. This starts at line 522 of FFmpeg/libavformat/aviobuf.c and is repeated here for convenience:

#if FF_API_OLD_AVIO_EOF_0
   if (!ret && !s->max_packet_size) {
        av_log(NULL, AV_LOG_WARNING, "Invalid return value 0 for stream protocol\n");
        ret = AVERROR_EOF;
    }

This workaround has been declared obsolete in 2017 and it is now removed from the FFmpeg in fixes/33 and master.
File reading for MythMusic is done by RemoteFile and this does not have a concept of end-of-file.
In MythMusic file mythmusic/remoteavformatcontext.h has a ReadFunc which uses RemoteFile to do the actual reading and then the result is passed to FFmpeg.
This is the place where the end-of-file status can be determined and passed back to FFmpeg.
Currently I am testing the following fix in my living room system:

    static int ReadFunc(void *opaque, uint8_t *buf, int buf_size)
    {
        auto *rf = reinterpret_cast< RemoteFile* >(opaque);
#if 0   // KdW test -- original
        return rf->Read(buf, buf_size);
#else
        int len = rf->Read(buf, buf_size);
        int ret = ((len == 0) && (buf_size > 0)) ? AVERROR_EOF : len;
        return ret;
#endif
    }

This file is used only by MythMusic so there is no risk for regressions in the rest of MythTV.
Therefore the essential part of this fix will be applied to master soon, with fixes/33 to follow a while later as is customary.

There are two side issues that might need looking at.
First, I never get error messages from FFmpeg even when logging option libav is enabled. The warning that should have been given because the EOF checking is done on length I have never seen.
Second, it could be that the EOF handling in the rest of MythTV needs looking at.
There can be, when playback ends at the end of a video, a large number of these messages:

2023-03-26 11:28:20.148050 E [1094967/1095408] Decoder avformatdecoder.cpp:4897:GetFrame  decoding error End of file (-541478725)
2023-03-26 11:28:20.148062 E [1094967/1095408] Decoder avformatdecoder.cpp:4897:GetFrame  decoding error End of file (-541478725)
2023-03-26 11:28:20.148074 E [1094967/1095408] Decoder avformatdecoder.cpp:4897:GetFrame  decoding error End of file (-541478725)
2023-03-26 11:28:20.148086 E [1094967/1095408] Decoder avformatdecoder.cpp:4897:GetFrame  decoding error End of file (-541478725)

However, that is for another day.

@ijc
Copy link
Contributor

ijc commented Mar 26, 2023

The problem is caused by how the end-of-file is handled.

Great find!

Currently I am testing the following fix in my living room system:

I've applied it to my v33 based system in the living room and it seems to have solved the issue AFAICT.

FWIW I think it looks like the right fix.

kmdewaal added a commit that referenced this issue Mar 26, 2023
Detect end-of-file when reading music files and return the AVERROR_EOF status to FFmpeg.
In version 33 MythTV has upgraded to a version of FFmpeg that does require this.

Refs #686
kmdewaal added a commit that referenced this issue Mar 28, 2023
Detect end-of-file when reading music files and return the AVERROR_EOF status to FFmpeg.
In version 33 MythTV has upgraded to a version of FFmpeg that does require this.

Refs #686

(cherry picked from commit b9354c9)
@kmdewaal
Copy link
Contributor Author

Thanks to all and especially to @ijc for helping to solve this issue. Fix is applied to master and fixes/33 so this ticket can now be closed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug:hang-deadlock Hangs or deadlocks component:plugins Issues with plugins version:master Master Development Branch
Projects
None yet
Development

No branches or pull requests

4 participants