search

ralph-irving / squeezelite

Lightweight headless squeezebox player for Lyrion Media Server
https://sourceforge.net/projects/lmsclients/files/squeezelite/
Other
382 stars 98 forks source link

Crash when reading Ogg metadata #222

Open nguillaumin opened 4 months ago

nguillaumin commented 4 months ago

Hi, I am experiencing crashes on Arch Linux, I think following an update of my system that replaced PulseAudio with PIpewire. Unfortunately I'm not too sure how to troubleshoot this.

For example, everything worked fine for a couple of hours then it crashed suddenly. In the system logs:

pr 28 15:17:19 htpc.home squeezelite[448]: [15:17:19.283545] stream_thread:628 headers: len: 491
Apr 28 15:17:19 htpc.home squeezelite[448]: HTTP/1.1 200 OK
Apr 28 15:17:19 htpc.home squeezelite[448]: Server: Logitech Media Server (8.4.0 - 1704454098)
Apr 28 15:17:19 htpc.home squeezelite[448]: Connection: close
Apr 28 15:17:19 htpc.home squeezelite[448]: Content-Type: audio/ogg
Apr 28 15:17:19 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-albumView=2; path=/
Apr 28 15:17:19 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
Apr 28 15:17:19 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-MY_MUSIC=1; path=/
Apr 28 15:17:19 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-FAVORITES=1; path=/
Apr 28 15:17:19 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-PLUGINS=1; path=/
Apr 28 15:17:19 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/
Apr 28 15:17:19 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-RADIO=1; path=/
Apr 28 15:17:19 htpc.home squeezelite[448]: 
Apr 28 15:17:19 htpc.home squeezelite[448]: [15:17:19.323569] stream_ogg:408 metadata: ALBUM=Vs.
Apr 28 15:17:19 htpc.home squeezelite[448]: [15:17:19.323626] stream_ogg:408 metadata: ARTIST=Pearl Jam
Apr 28 15:17:19 htpc.home squeezelite[448]: [15:17:19.323686] stream_ogg:408 metadata: TITLE=Dissident
Apr 28 15:17:19 htpc.home squeezelite[448]: [15:17:19.323735] stream_ogg:416 metadata length: 46
Apr 28 15:17:19 htpc.home squeezelite[448]: [15:17:19.343295] vorbis_decode:167 setting track_start
Apr 28 15:17:19 htpc.home squeezelite[448]: [15:17:19.343346] _checkfade:294 fade mode: 1 duration: 2 track-start
Apr 28 15:17:19 htpc.home squeezelite[448]: [15:17:19.343367] _checkfade:334 CROSSFADE: 88200 frames
Apr 28 15:17:26 htpc.home squeezelite[448]: [15:17:26.904135] _output_frames:153 track start sample rate: 44100 replay_gain: 28416
Apr 28 15:17:26 htpc.home squeezelite[448]: [15:17:26.904236] _output_frames:181 fade start reached
Apr 28 15:17:28 htpc.home squeezelite[448]: [15:17:28.898750] _output_frames:204 crossfade complete
Apr 28 15:17:28 htpc.home squeezelite[448]: [15:17:28.898810] _output_frames:207 skipped crossfaded start
Apr 28 15:19:22 htpc.home squeezelite[448]: [15:19:22.231644] stream_thread:702 end of stream (5124378 bytes)
Apr 28 15:20:52 htpc.home squeezelite[448]: [15:20:52.528124] vorbis_decode:274 end of decode
Apr 28 15:20:52 htpc.home squeezelite[448]: [15:20:52.528183] decode_thread:100 decode complete
Apr 28 15:20:52 htpc.home squeezelite[448]: [15:20:52.528205] _checkfade:294 fade mode: 1 duration: 2 track-end
Apr 28 15:20:52 htpc.home squeezelite[448]: [15:20:52.735201] codec_open:272 codec open: 'o'
Apr 28 15:20:52 htpc.home squeezelite[448]: [15:20:52.735345] connect_socket:235 connecting to 192.168.1.8:9000
Apr 28 15:20:52 htpc.home squeezelite[448]: [15:20:52.735674] stream_sock:921 header: GET /stream.mp3?player=00:00:00:00:00:00 HTTP/1.0
Apr 28 15:20:52 htpc.home squeezelite[448]: 
Apr 28 15:20:52 htpc.home squeezelite[448]: [15:20:52.746937] stream_thread:628 headers: len: 491
Apr 28 15:20:52 htpc.home squeezelite[448]: HTTP/1.1 200 OK
Apr 28 15:20:52 htpc.home squeezelite[448]: Server: Logitech Media Server (8.4.0 - 1704454098)
Apr 28 15:20:52 htpc.home squeezelite[448]: Connection: close
Apr 28 15:20:52 htpc.home squeezelite[448]: Content-Type: audio/ogg
Apr 28 15:20:52 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-albumView=2; path=/
Apr 28 15:20:52 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
Apr 28 15:20:52 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-MY_MUSIC=1; path=/
Apr 28 15:20:52 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-FAVORITES=1; path=/
Apr 28 15:20:52 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-PLUGINS=1; path=/
Apr 28 15:20:52 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/
Apr 28 15:20:52 htpc.home squeezelite[448]: Set-Cookie: Squeezebox-expanded-RADIO=1; path=/
Apr 28 15:20:52 htpc.home squeezelite[448]: 
Apr 28 15:20:52 htpc.home squeezelite[448]: [15:20:52.772991] stream_ogg:408 metadata: ALBUM=Les 100 plus belles chansons
Apr 28 15:20:52 htpc.home kernel: squeezelite[469]: segfault at 7e63d8001b91 ip 00005f3b308223c0 sp 00007e62fa7be830 error 4 in squeezelite[5f3b3081b000+17000] likely on CPU 1 (core 1, socket>
Apr 28 15:20:52 htpc.home kernel: Code: 00 03 00 00 00 85 d2 0f 84 3e 01 00 00 89 55 98 4c 89 6d 90 4c 89 b5 70 ff ff ff 48 89 9d 78 ff ff ff 4c 89 e3 0f 1f 44 00 00 <44> 0f be 2b 48 83 c3 04>
Apr 28 15:20:52 htpc.home systemd[1]: Created slice Slice /system/systemd-coredump.
Apr 28 15:20:52 htpc.home systemd[1]: Started Process Core Dump (PID 1243/UID 0).
Apr 28 15:20:53 htpc.home systemd-coredump[1244]: [🡕] Process 448 (squeezelite) of user 967 dumped core.

                                                  Stack trace of thread 469:
                                                  #0  0x00005f3b308223c0 stream_ogg (squeezelite + 0xc3c0)
                                                  #1  0x00007e62f78a955a n/a (libc.so.6 + 0x8b55a)
                                                  #2  0x00007e62f7926a5c n/a (libc.so.6 + 0x108a5c)

                                                  Stack trace of thread 448:
                                                  #0  0x00007e62f79190df __poll (libc.so.6 + 0xfb0df)
                                                  #1  0x00005f3b30820b3d poll (squeezelite + 0xab3d)
                                                  #2  0x00005f3b3081cb24 main (squeezelite + 0x6b24)
                                                  #3  0x00007e62f7843cd0 n/a (libc.so.6 + 0x25cd0)
                                                  #4  0x00007e62f7843d8a __libc_start_main (libc.so.6 + 0x25d8a)
                                                  #5  0x00005f3b3081dff5 _start (squeezelite + 0x7ff5)

                                                  Stack trace of thread 496:
                                                  #0  0x00007e62f78f2335 clock_nanosleep (libc.so.6 + 0xd4335)
                                                  #1  0x00007e62f78fd3e7 __nanosleep (libc.so.6 + 0xdf3e7)
                                                  #2  0x00007e62f7926589 usleep (libc.so.6 + 0x108589)
                                                  #3  0x00005f3b30827f24 decode_thread (squeezelite + 0x11f24)
                                                  #4  0x00007e62f78a955a n/a (libc.so.6 + 0x8b55a)
                                                  #5  0x00007e62f7926a5c n/a (libc.so.6 + 0x108a5c)

                                                  Stack trace of thread 495:
                                                  #0  0x00007e62f79190df __poll (libc.so.6 + 0xfb0df)
                                                  #1  0x00007e62fa717bc9 n/a (libasound.so.2 + 0x6dbc9)
                                                  #2  0x00007e62fa72af16 snd_pcm_wait (libasound.so.2 + 0x80f16)
                                                  #3  0x00005f3b30826255 output_thread (squeezelite + 0x10255)
                                                  #4  0x00007e62f78a955a n/a (libc.so.6 + 0x8b55a)
                                                  #5  0x00007e62f7926a5c n/a (libc.so.6 + 0x108a5c)
                                                  ELF object binary architecture: AMD x86-64
Apr 28 15:20:53 htpc.home systemd[1]: systemd-coredump@0-1243-0.service: Deactivated successfully.
Apr 28 15:20:53 htpc.home systemd[1]: squeezelite.service: Main process exited, code=dumped, status=11/SEGV
Apr 28 15:20:53 htpc.home systemd[1]: squeezelite.service: Failed with result 'core-dump'.
Apr 28 15:20:53 htpc.home systemd[1]: squeezelite.service: Consumed 2min 44.793s CPU time.

Attached dumped core:
core.squeezelite.967.745223802fc8470a98e5e231d7c14080.448.1714310452000000.zst.gz

Then after that it fails to restart:

Apr 28 15:25:12 htpc.home squeezelite[1339]: [15:25:12.909312] stream_init:756 init stream
Apr 28 15:25:12 htpc.home squeezelite[1339]: [15:25:12.909602] output_init_alsa:936 init output
Apr 28 15:25:12 htpc.home squeezelite[1339]: [15:25:12.909625] output_init_alsa:975 requested alsa_buffer: 40 alsa_period: 4 format: any mmap: 1
Apr 28 15:25:12 htpc.home squeezelite[1339]: [15:25:12.912967] ALSA _snd_pcm_direct_new:2180 unable to create IPC semaphore
Apr 28 15:25:12 htpc.home squeezelite[1339]: [15:25:12.912986] test_open:281 playback open error: Permission denied
Apr 28 15:25:12 htpc.home squeezelite[1339]: [15:25:12.912991] output_init_common:401 unable to open output device: default
Apr 28 15:25:12 htpc.home systemd[494]: squeezelite.service: Main process exited, code=exited, status=1/FAILURE

It looks like it cannot access the audio device somehow? When I try using aplay I get a similar error:

$ aplay /usr/share/sounds/alsa/Front_Left.wav 
ALSA lib pcm_direct.c:2180:(_snd_pcm_direct_new) unable to create IPC semaphore
aplay: main:850: audio open error: Permission denied

I'm not sure where to go from there unfortunately...

nguillaumin commented 5 days ago

I was able to narrow down the issue I think, and it seems to be due to specific tracks streamed by LMS! For example:

Sep 14 15:19:01 htpc squeezelite[32292]: [15:19:01.712922] decode_flush:244 decode flush
Sep 14 15:19:01 htpc squeezelite[32292]: [15:19:01.712947] output_flush:439 flush output buffer (full)
Sep 14 15:19:01 htpc squeezelite[32292]: [15:19:01.792645] codec_open:278 codec open: 'o'
Sep 14 15:19:01 htpc squeezelite[32292]: [15:19:01.792726] connect_socket:237 connecting to 192.168.1.8:9000
Sep 14 15:19:01 htpc squeezelite[32292]: [15:19:01.792997] stream_sock:923 header: GET /stream.mp3?player=04:d4:c4:4f:32:ec HTTP/1.0
Sep 14 15:19:01 htpc squeezelite[32292]:
Sep 14 15:19:01 htpc squeezelite[32292]: [15:19:01.898695] stream_thread:630 headers: len: 491
Sep 14 15:19:01 htpc squeezelite[32292]: HTTP/1.1 200 OK
Sep 14 15:19:01 htpc squeezelite[32292]: Server: Logitech Media Server (8.4.0 - 1704454098)
Sep 14 15:19:01 htpc squeezelite[32292]: Connection: close
Sep 14 15:19:01 htpc squeezelite[32292]: Content-Type: audio/ogg
Sep 14 15:19:01 htpc squeezelite[32292]: Set-Cookie: Squeezebox-albumView=2; path=/
Sep 14 15:19:01 htpc squeezelite[32292]: Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
Sep 14 15:19:01 htpc squeezelite[32292]: Set-Cookie: Squeezebox-expanded-MY_MUSIC=1; path=/
Sep 14 15:19:01 htpc squeezelite[32292]: Set-Cookie: Squeezebox-expanded-FAVORITES=1; path=/
Sep 14 15:19:01 htpc squeezelite[32292]: Set-Cookie: Squeezebox-expanded-PLUGINS=1; path=/
Sep 14 15:19:01 htpc squeezelite[32292]: Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/
Sep 14 15:19:01 htpc squeezelite[32292]: Set-Cookie: Squeezebox-expanded-RADIO=1; path=/
Sep 14 15:19:01 htpc squeezelite[32292]:
Sep 14 15:19:01 htpc squeezelite[32292]: [15:19:01.898965] stream_ogg:410 metadata: ALBUM=Voyage, Voyage: Greatest Hits

Track attached: Desireless - Voyage, voyage.zip

Playing this track immediately crashes Squeezelite.

nguillaumin commented 4 days ago

I could narrow it down further to the reading of the Ogg metadata. Around here: https://github.com/ralph-irving/squeezelite/blob/master/stream.c#L399 . Somehow len at some point gets corrupted.

I realized the file I attached above has completely messed up metadata, but it should not cause a crash ideally.

philippe44 commented 4 days ago

I did the OggMetadata changes in squeezelite, especially to support chained streams and feedback metadata to LMS as before only real SB could.

I don't have computer access for now but depending what you mean by "messed up metadata" I think that if they have a totally wrong encoding, the yes it might happen that the parser crashes.

It might a debate with polarized opinions, but as somebody coding for free open source, I can't take the time and don't want to bloat code for handling all sort of improbable input-related errors. If it's human inputs, yes, but when it is a file that is supposed to be spit out by an encoder, then the encoder must be fixed.

As a general opinion, I think we destroy standards and code quality when we decide to accept all and any non-compliant protocols and files. UPnP is as very good example of that.

It should be a Darwinian process: your apps is not compatible, it should be selected out...

nguillaumin commented 4 days ago

Thanks for your reply.

In this case the file is still valid and not corrupted, it's just that the metadata is weird, big and very repetitive (due to: https://github.com/beetbox/beets/issues/4528 )

DISCID=F30ECC10
ACOUSTID_FINGERPRINT=
ACOUSTID_ID=
ALBUM=Voyage, Voyage: Greatest Hits
ALBUMARTIST_CREDIT=Desireless
ALBUMARTISTSORT=Desireless
MUSICBRAINZ_ALBUMCOMMENT=
RELEASESTATUS=Official
MUSICBRAINZ_ALBUMSTATUS=Official
RELEASETYPE=[
RELEASETYPE='
RELEASETYPE=[
RELEASETYPE='
RELEASETYPE=,
RELEASETYPE= 
[...] about 230'000 lines like this
RELEASETYPE=,
RELEASETYPE= 
RELEASETYPE='
RELEASETYPE=]
RELEASETYPE='
RELEASETYPE=]
MUSICBRAINZ_ALBUMTYPE=[
MUSICBRAINZ_ALBUMTYPE='
MUSICBRAINZ_ALBUMTYPE=[
MUSICBRAINZ_ALBUMTYPE='
MUSICBRAINZ_ALBUMTYPE=,
[...] another 230'000 or so lines
MUSICBRAINZ_ALBUMTYPE= 
MUSICBRAINZ_ALBUMTYPE='
MUSICBRAINZ_ALBUMTYPE=]
MUSICBRAINZ_ALBUMTYPE='
MUSICBRAINZ_ALBUMTYPE=]
ARRANGER=
ARTIST=Desireless
ARTIST_CREDIT=Desireless
ARTISTSORT=Desireless
ASIN=B0000A0I6Z
BPM=0

Metadata attached: vorbiscomment.txt

So without entering the debate too much :wink: , still a valid file I think (passes oggz-validate and vorbiscomment) that ideally shouldn't cause a crash.

Braklet commented 4 days ago

So the weird/big/repetitive issue is caused by a beet bug (now apparently fixed)? While I agree that a parsing crash in SL is less than optimal, seems that the right approach would be to address the weird/big/repetitive metadata issue first. Just my opinion, not trying to wade into an argument. BL

nguillaumin commented 4 days ago

The Beet bug is fixed indeed, and I fixed the metadata in my files. So for me, it's good as it is. However I suspect it reveals a weakness in the metadata parser that might be worth looking into...