ostrosablin
commented
2 years ago This seems be similar to #1440 - same message
mpg123: mpg123_getformat() failed: Message: I am done with this track.
Closed dvzrv closed 2 years ago
ostrosablin
commented
2 years ago This seems be similar to #1440 - same message
mpg123: mpg123_getformat() failed: Message: I am done with this track.
MaxKellermann
commented
2 years ago I can't reproduce the problem with FFmpeg 5.0. Does this affect all files, or just some file types, or just one file? Please post a backtrace of MPD while the update hangs (of the update thread, or of all threads).
dvzrv
commented
2 years ago Does this affect all files, or just some file types, or just one file?
For now I think it has only been happening with .mp3 files, but I can't say for sure (it hangs after the first file). For that I need to create a test setup.
Please post a backtrace of MPD while the update hangs (of the update thread, or of all threads).
Can't promise I will get to this today. Got a lot of other tickets to work on atm. I'll try tomorrow!
nitsvga
commented
2 years ago Happening to me as well on Artix with runit. I think it should be noted that it starts to happen at like the 70% percent of my library which is huge (~1TB). But that never occurred before until ffmpeg updated to 5.0.
ffmpeg version n5.0 Copyright (c) 2000-2022 the FFmpeg developers
built with gcc 11.2.0 (GCC)Music Player Daemon 0.23.5 (0.23.5)
Copyright 2003-2007 Warren Dukes <warren.dukes@gmail.com>
Copyright 2008-2021 Max Kellermann <max.kellermann@gmail.com>
This is free software; see the source for copying conditions. There is NO
warranty; not even MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
Database plugins:
simple proxy upnp
Storage plugins:
local udisks nfs curl
Neighbor plugins:
upnp udisks
Decoders plugins:
[mad] mp3 mp2
[mpg123] mp3
[vorbis] ogg oga
[oggflac] ogg oga
[flac] flac
[opus] opus ogg oga
[sndfile] wav aiff aif au snd paf iff svx sf voc w64 pvf xi htk caf sd2
[audiofile] wav au aiff aif
[dsdiff] dff
[dsf] dsf
[hybrid_dsd] m4a
[faad] aac
[mpcdec] mpc
[wavpack] wv
[openmpt] mptm mod s3m xm it 669 amf ams c67 dbm digi dmf dsm dtm far imf ice j2b m15 mdl med mms mt2 mtm nst okt plm psm pt36 ptm sfx sfx2 st26 stk stm stp ult wow gdm mo3 oxm umx xpk ppm mmcmp
[modplug] 669 amf ams dbm dfm dsm far it med mdl mod mtm mt2 okt s3m stm ult umx xm
[mikmod] amf dsm far gdm imf it med mod mtm s3m stm stx ult uni xm
[sidplay] sid mus str prg P00
[wildmidi] mid
[fluidsynth] mid
[ffmpeg] 16sv 3g2 3gp 4xm 8svx aa3 aac ac3 adx afc aif aifc aiff al alaw amr anim apc ape asf atrac au aud avi avm2 avs bap bfi c93 cak cin cmv cpk daud dct divx dts dv dvd dxa eac3 film flac flc fli fll flx flv g726 gsm gxf iss m1v m2v m2t m2ts m4a m4b m4v mad mj2 mjpeg mjpg mka mkv mlp mm mmf mov mp+ mp1 mp2 mp3 mp4 mpc mpeg mpg mpga mpp mpu mve mvi mxf nc nsv nut nuv oga ogm ogv ogx oma ogg omg opus psp pva qcp qt r3d ra ram rl2 rm rmvb roq rpl rvc shn smk snd sol son spx str swf tak tgi tgq tgv thp ts tsp tta xa xvid uv uv2 vb vid vob voc vp6 vmd wav webm wma wmv wsaud wsvga wv wve rtp:// rtsp:// rtsps://
[gme] ay gbs gym hes kss nsf nsfe rsn sap spc vgm vgz
[pcm]
Filters:
libsamplerate soxr
Tag plugins:
id3tag
Output plugins:
shout null fifo pipe alsa ao oss openal solaris pipewire pulse jack httpd snapcast recorder
Encoder plugins:
null vorbis opus lame twolame wave flac
Archive plugins:
[bz2] bz2
[zzip] zip
[iso] iso
Input plugins:
file io_uring archive alsa qobuz curl ffmpeg nfs mms cdio_paranoia
Playlist plugins:
extm3u m3u pls xspf asx rss soundcloud flac cue embcue
Protocols:
file:// alsa:// cdda:// ftp:// ftps:// gopher:// hls+http:// hls+https:// http:// https:// mms:// mmsh:// mmst:// mmsu:// nfs:// qobuz:// rtmp:// rtmpe:// rtmps:// rtmpt:// rtmpte:// rtmpts:// rtp:// rtsp:// rtsps:// scp:// sftp:// smb:// srtp://
Other features:
avahi dbus udisks epoll icu inotify ipv6 tcp unFeb 19 21:41 : mpg123: mpg123_getformat() failed: Message: I am done with this track.
crides
commented
2 years ago Hi, I'm also suffering from this issue.
It appears that the mesage I am done with this track has occured on my system before, so that doesn't seem to be the problem.
Building on 718ae433b and GDB'ing gives:
(gdb) bt
#0 0x00007ffff30bf9ae in epoll_wait () at /usr/lib/libc.so.6
#1 0x000055555565e2fc in EpollFD::Wait(epoll_event*, int, int) (this=0x7fffffffad58, events=0x7fffffffa230, maxevents=16, timeout=-1)
at ../src/system/EpollFD.hxx:55
#2 0x000055555565e52f in EpollBackend::ReadEvents(int) (this=0x7fffffffad58, timeout_ms=-1) at ../src/event/EpollBackend.hxx:60
#3 0x000055555565f342 in EventLoop::Wait(std::chrono::duration<long, std::ratio<1l, 1000000000l> >) (this=0x7fffffffa4c8, timeout=...)
at ../src/event/Loop.cxx:252
#4 0x000055555565f6f2 in EventLoop::Run() (this=0x7fffffffa4c8) at ../src/event/Loop.cxx:343
#5 0x00005555555b8dc5 in MainConfigured(CommandLineOptions const&, ConfigData const&) (options=..., raw_config=...) at ../src/Main.cxx:517
#6 0x00005555555b9172 in MainOrThrow(int, char**) (argc=3, argv=0x7fffffffc3d8) at ../src/Main.cxx:602
#7 0x00005555555b91db in mpd_main(int, char**) (argc=3, argv=0x7fffffffc3d8) at ../src/Main.cxx:608
#8 0x00005555555b923d in main(int, char**) (argc=3, argv=0x7fffffffc3d8) at ../src/Main.cxx:620The waited Epoll has fd 5, and:
$ lsof -p 1822494
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
...
mpd 1822494 steven 0r CHR 1,3 0t0 5 /dev/null
mpd 1822494 steven 1w REG 8,18 23730076 3934049 /home/steven/.local/mpd/mpd.log
mpd 1822494 steven 2w REG 8,18 23730076 3934049 /home/steven/.local/mpd/mpd.log
mpd 1822494 steven 3u a_inode 0,14 0 11295 [signalfd]
mpd 1822494 steven 4u a_inode 0,14 0 11295 [eventfd:262]
mpd 1822494 steven 5u a_inode 0,14 0 11295 [eventpoll:3,4,10,11,20]
mpd 1822494 steven 6u a_inode 0,14 0 11295 [eventfd:263]
mpd 1822494 steven 7u a_inode 0,14 0 11295 [eventpoll:6,13,16]
mpd 1822494 steven 8u a_inode 0,14 0 11295 [eventfd:264]
mpd 1822494 steven 9u a_inode 0,14 0 11295 [eventpoll:8]
mpd 1822494 steven 10u unix 0x00000000023b046d 0t0 37181088 /run/user/1000/mpd/socket type=STREAM (LISTEN)
mpd 1822494 steven 11u IPv6 37181090 0t0 TCP *:mshvlm (LISTEN)
mpd 1822494 steven 12u REG 8,18 12288 3939272 /home/steven/.local/mpd/sticker.sql
mpd 1822494 steven 13u a_inode 0,14 0 11295 [io_uring]
mpd 1822494 steven 14u unix 0x000000004cf23fd3 0t0 37181094 type=STREAM (CONNECTED)
mpd 1822494 steven 15u unix 0x00000000d2e72974 0t0 37181095 type=STREAM (CONNECTED)
mpd 1822494 steven 16u unix 0x0000000040a4b5ec 0t0 37181587 type=STREAM (CONNECTED)
mpd 1822494 steven 17r DIR 8,18 4096 4462585 /home/steven/Music
mpd 1822494 steven 18r DIR 8,18 4096 4496730 /home/steven/Music/Approaching Nirvana
mpd 1822494 steven 19r DIR 8,18 4096 4497198 /home/steven/Music/Approaching Nirvana/Legacy Collection
mpd 1822494 steven 20u IPv6 37181098 0t0 TCP localhost:mshvlm->localhost:56780 (ESTABLISHED)
mpd 1822494 steven 21r REG 8,18 0 4497203 /home/steven/Music/Approaching Nirvana/Legacy Collection/Anxiety Cure (I@crides your backtrace is not helpful, it's of the main thread, and I asked for a backtrace of the update thread.
crides
commented
2 years ago Sorry, I should've thought about it. Here's the backtrace (all other 3 are epoll'ing):
#0 0x00005555556857ac in InjectEvent::GetEventLoop() const (this=0x0) at ../src/event/InjectEvent.hxx:52
#1 0x00005555556857d6 in AsyncInputStream::GetEventLoop() const (this=0x7fffd8019a70) at ../src/input/plugins/../AsyncInputStream.hxx:80
#2 0x00005555556ac112 in AsyncInputStream::Read(std::unique_lock<std::mutex>&, void*, unsigned long)
(this=0x7fffd8019a70, lock=..., ptr=0x7fffd80987e0, read_size=16384) at ../src/input/AsyncInputStream.cxx:178
#3 0x00005555556aa4f1 in InputStream::LockRead(void*, unsigned long) (this=0x7fffd8019a70, ptr=0x7fffd80987e0, _size=16384)
at ../src/input/InputStream.cxx:120
#4 0x000055555572ad79 in decoder_read(DecoderClient*, InputStream&, void*, unsigned long)
(client=0x0, is=..., buffer=0x7fffd80987e0, length=16384) at ../src/decoder/DecoderAPI.cxx:38
#5 0x00005555557281dc in AvioStream::Read(void*, int) (this=0x7fffe116ea40, dest=0x7fffd80987e0, size=16384)
at ../src/decoder/plugins/FfmpegIo.cxx:38
#6 0x0000555555728349 in AvioStream::_Read(void*, unsigned char*, int) (opaque=0x7fffe116ea40, buf=0x7fffd80987e0 "", size=16384)
at ../src/decoder/plugins/FfmpegIo.cxx:82
#7 0x00007ffff7ccacd6 in avio_read () at /usr/lib/libavformat.so.59
#8 0x00007ffff7d0af03 in av_probe_input_buffer2 () at /usr/lib/libavformat.so.59
#9 0x00007ffff7ceec63 in avformat_open_input () at /usr/lib/libavformat.so.59
#10 0x000055555570f394 in Ffmpeg::FormatContext::OpenInput(char const*, AVInputFormat*, AVDictionary**)
(this=0x7fffe116ea38, url=0x7fffd80603d0 "/home/steven/Music/Approaching Nirvana/Legacy Collection/Anxiety Cure (Instrumental).mp3", fmt=0x0, options=0x7fffe116e9d0) at ../src/lib/ffmpeg/Format.hxx:64
#11 0x000055555570f86d in FfmpegOpenInput(AVIOContext*, char const*, AVInputFormat*)
(pb=0x7fffd8083780, filename=0x7fffd80603d0 "/home/steven/Music/Approaching Nirvana/Legacy Collection/Anxiety Cure (Instrumental).mp3", fmt=0x0) at ../src/decoder/plugins/FfmpegDecoderPlugin.cxx:77
#12 0x0000555555711071 in ffmpeg_scan_stream(InputStream&, TagHandler&) (is=..., handler=...)
at ../src/decoder/plugins/FfmpegDecoderPlugin.cxx:662
#13 0x00005555556232df in DecoderPlugin::ScanStream(InputStream&, TagHandler&) const
(this=0x5555558e8b60 <ffmpeg_decoder_plugin>, is=..., handler=...) at ../src/decoder/DecoderPlugin.hxx:235
#14 0x0000555555623483 in TagFileScan::ScanStream(DecoderPlugin const&) (this=0x7fffe116ebc0, plugin=...) at ../src/TagFile.cxx:64
#15 0x0000555555623519 in TagFileScan::Scan(DecoderPlugin const&) (this=0x7fffe116ebc0, plugin=...) at ../src/TagFile.cxx:69
#16 0x0000555555623566 in operator()(DecoderPlugin const&) const (__closure=0x7fffe116eb58, plugin=...) at ../src/TagFile.cxx:88
#17 0x0000555555623879 in decoder_plugins_try<ScanFileTagsNoGeneric(Path, TagHandler&)::<lambda(const DecoderPlugin&)> >(struct {...}) (f=...)
at ../src/decoder/DecoderList.hxx:72
--Type <RET> for more, q to quit, c to continue without paging--c
#18 0x0000555555623660 in ScanFileTagsNoGeneric(Path, TagHandler&) (path_fs=..., handler=...) at ../src/TagFile.cxx:87
#19 0x000055555562370c in ScanFileTagsWithGeneric(Path, TagBuilder&, AudioFormat*) (path=..., builder=..., audio_format=0x7fffe116eca8) at ../src/TagFile.cxx:98
#20 0x000055555561def4 in Song::UpdateFile(Storage&) (this=0x7fffd8083690, storage=...) at ../src/SongUpdate.cxx:90
#21 0x000055555561dc4c in Song::LoadFile(Storage&, char const*, Directory&) (storage=..., path_utf8=0x7fffd8083460 "Anxiety Cure (Instrumental).mp3", parent=...) at ../src/SongUpdate.cxx:59
#22 0x0000555555745389 in UpdateWalk::UpdateSongFile2(Directory&, char const*, std::basic_string_view<char, std::char_traits<char> >, StorageFileInfo const&) (this=0x5555559b2ff0, directory=..., name=0x7fffd8083460 "Anxiety Cure (Instrumental).mp3", suffix="mp3", info=...) at ../src/db/update/UpdateSong.cxx:66
#23 0x0000555555745682 in UpdateWalk::UpdateSongFile(Directory&, char const*, std::basic_string_view<char, std::char_traits<char> >, StorageFileInfo const&) (this=0x5555559b2ff0, directory=..., name=0x7fffd8083460 "Anxiety Cure (Instrumental).mp3", suffix="mp3", info=...) at ../src/db/update/UpdateSong.cxx:108
#24 0x0000555555741bc8 in UpdateWalk::UpdateRegularFile(Directory&, char const*, StorageFileInfo const&) (this=0x5555559b2ff0, directory=..., name=0x7fffd8083460 "Anxiety Cure (Instrumental).mp3", info=...) at ../src/db/update/Walk.cxx:195
#25 0x0000555555741d5b in UpdateWalk::UpdateDirectoryChild(Directory&, ExcludeList const&, char const*, StorageFileInfo const&) (this=0x5555559b2ff0, directory=..., exclude_list=..., name=0x7fffd8083460 "Anxiety Cure (Instrumental).mp3", info=...) at ../src/db/update/Walk.cxx:208
#26 0x00005555557428f3 in UpdateWalk::UpdateDirectory(Directory&, ExcludeList const&, StorageFileInfo const&) (this=0x5555559b2ff0, directory=..., exclude_list=..., info=...) at ../src/db/update/Walk.cxx:385
#27 0x0000555555741e3d in UpdateWalk::UpdateDirectoryChild(Directory&, ExcludeList const&, char const*, StorageFileInfo const&) (this=0x5555559b2ff0, directory=..., exclude_list=..., name=0x7fffd8095df0 "Legacy Collection", info=...) at ../src/db/update/Walk.cxx:222
#28 0x00005555557428f3 in UpdateWalk::UpdateDirectory(Directory&, ExcludeList const&, StorageFileInfo const&) (this=0x5555559b2ff0, directory=..., exclude_list=..., info=...) at ../src/db/update/Walk.cxx:385
#29 0x0000555555741e3d in UpdateWalk::UpdateDirectoryChild(Directory&, ExcludeList const&, char const*, StorageFileInfo const&) (this=0x5555559b2ff0, directory=..., exclude_list=..., name=0x7fffd8033360 "Approaching Nirvana", info=...) at ../src/db/update/Walk.cxx:222
#30 0x00005555557428f3 in UpdateWalk::UpdateDirectory(Directory&, ExcludeList const&, StorageFileInfo const&) (this=0x5555559b2ff0, directory=..., exclude_list=..., info=...) at ../src/db/update/Walk.cxx:385
#31 0x00005555557432bf in UpdateWalk::Walk(Directory&, char const*, bool) (this=0x5555559b2ff0, root=..., path=0x5555559833e0 "", discard=true) at ../src/db/update/Walk.cxx:529
#32 0x000055555573dae4 in UpdateService::Task() (this=0x555555983330) at ../src/db/update/Service.cxx:122
#33 0x000055555573e93c in BindMethodDetail::WrapperGenerator<void (UpdateService::*)() noexcept, &UpdateService::Task>::Invoke(void*) (_instance=0x555555983330) at ../src/util/BindMethod.hxx:130
#34 0x00005555556582ae in BoundMethod<void () noexcept>::operator()() const (this=0x555555983380) at ../src/util/BindMethod.hxx:78
#35 0x0000555555665a04 in Thread::Run() (this=0x555555983380) at ../src/thread/Thread.cxx:63
#36 0x0000555555665a35 in Thread::ThreadProc(void*) (ctx=0x555555983380) at ../src/thread/Thread.cxx:92
#37 0x00007ffff303a5c2 in start_thread () at /usr/lib/libc.so.6
#38 0x00007ffff30bf584 in clone () at /usr/lib/libc.so.6At that code position, MPD cannot block. Is this a busy loop? When you interrupt the process in gdb, do you always see this code position, or do you see different ones?
crides
commented
2 years ago This is a busy loop. From GDB I'm seeing these locations:
#0 0x000055555572834a in AvioStream::_Read(void*, unsigned char*, int)
(opaque=0x7fffe17aea40, buf=0x7fffd806ae70 "", size=16384) at ../src/decoder/plugins/FfmpegIo.cxx:83#0 0x00005555556aa4f9 in InputStream::LockRead(void*, unsigned long)
(this=0x7fffd8009dc0, ptr=0x7fffd806ae70, _size=16384) at ../src/input/InputStream.cxx:121#0 0x00005555555c2dc3 in std::mutex::lock() (this=0x7fffe17aebd8) at /usr/include/c++/11.1.0/bits/std_mutex.h:105
#1 0x00005555555c9407 in std::unique_lock<std::mutex>::lock() (this=0x7fffe17ae6c0) at /usr/include/c++/11.1.0/bits/unique_lock.h:139
#2 0x000055555558c7a5 in std::unique_lock<std::mutex>::unique_lock(std::mutex&) (this=0x7fffe17ae6c0, __m=..., this=<optimized out>, __m=<optimized out>) at /usr/include/c++/11.1.0/bits/unique_lock.h:69
#3 0x00005555556aa4cd in InputStream::LockRead(void*, unsigned long) (this=0x7fffd8009dc0, ptr=0x7fffd806ae70, _size=16384) at ../src/input/InputStream.cxx:119#0 0x00007ffff311d4d4 in __memmove_avx_unaligned_erms () at /usr/lib/libc.so.6
#1 0x00005555556ac1f6 in AsyncInputStream::Read(std::unique_lock<std::mutex>&, void*, unsigned long)
(this=0x7fffd8009dc0, lock=..., ptr=0x7fffd806ae70, read_size=16384) at ../src/input/AsyncInputStream.cxx:196
#2 0x00005555556aa4f1 in InputStream::LockRead(void*, unsigned long)
(this=0x7fffd8009dc0, ptr=0x7fffd806ae70, _size=16384) at ../src/input/InputStream.cxx:120Hope this helps
crides
commented
2 years ago Okay I figured out my side of the problem. There are some files that are empty for some reason, and it seems like that error is hanging MPD. Once I got rid of them it's fine
MaxKellermann
commented
2 years ago Thanks @crides, that was a good hint: FFmpeg gets stuck on empty files (and this has nothing to do with 5.0; it occurs with 4.4 as well). Fix is scheduled for 0.23.6.
Bug report
Describe the bug
Hi! I'm packaging mpd for Arch Linux. We recently rebuilt a lot of packages against ffmpeg 5.0 and mpd was one of them. Since the rebuild mpd can not update its database anymore (I suspect this has to do with the examination of files).
When rebuilding mpd against a ffmpeg 4.4 compatibility library, the updates are working again.
See FS#73873 for the downstream ticket.
Expected Behavior
Mpd is linked against ffmpeg 5.0 and database is updated.
Actual Behavior
When built/linked against ffmpeg 5.0, mpd stalls doing the update (seemingly after one file) and also blocks stopping the service. It is still possible to play back audio using mpd in the meantime.
Version
Log
The below log shows the behavior when mpd is linked against ffmpeg 5.0 and when trying to trigger a database update with
mpc update(while no audio is playing).