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.

Sign up for GitHub

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

Jump to bottom

Crash when reading Ogg metadata #222

Open
nguillaumin opened this issue Apr 28, 2024 · 6 comments
Open

Crash when reading Ogg metadata #222

nguillaumin opened this issue Apr 28, 2024 · 6 comments

Comments

@nguillaumin
Copy link

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
Copy link
Author

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 nguillaumin changed the title Crash on Arch Linux Crash when reading Ogg metadata Sep 15, 2024
@nguillaumin
Copy link
Author

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
Copy link

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
Copy link
Author

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: beetbox/beets#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 😉 , still a valid file I think (passes oggz-validate and vorbiscomment) that ideally shouldn't cause a crash.

@Braklet
Copy link

Braklet commented Sep 15, 2024 via email

@nguillaumin
Copy link
Author

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...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@nguillaumin @Braklet @philippe44