ralph-irving / squeezelite

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

Helicopter noise instead of music #149

Open Vinndimon opened 2 years ago

Vinndimon commented 2 years ago

I use Squeezelite on Ubuntu 20.04. Sometimes, randomly, it loses the ability to play music. Instead of music it plays some strange "helicopter" noise. The decoder skips frames according to the log:

[23:46:54.206332] stream_init:454 init stream
[23:46:54.208194] output_init_alsa:933 init output
[23:46:54.208255] output_init_alsa:973 requested alsa_buffer: 40 alsa_period: 4 format: any mmap: 1
[23:46:54.220820] output_init_common:432 supported rates: 384000 352800 192000 176400 96000 88200 48000 44100 32000 24000 22500 16000 12000 11025 8000 
[23:46:54.220987] output_init_alsa:997 unable to lock memory: Cannot allocate memory
[23:46:54.221143] output_init_alsa:1005 glibc detected using mallopt
[23:46:54.223658] decode_init:153 init decode
[23:46:54.223658] output_thread:682 open output device: default
[23:46:54.223779] register_dsd:908 using dsd to decode dsf,dff
[23:46:54.223818] alsa_open:351 opening device at: 44100
[23:46:54.225942] alsa_open:422 opened device default using format: S32_LE sample rate: 44100 mmap: 0
[23:46:54.226012] alsa_open:513 buffer: 40 period: 4 -> buffer size: 1764 period size: 441
[23:46:55.017393] load_faad:633 loaded libfaad.so.2
[23:46:55.017445] register_faad:663 using faad to decode aac
[23:46:55.025044] load_vorbis:356 loaded libvorbisfile.so.3
[23:46:55.025097] register_vorbis:385 using vorbis to decode ogg
[23:46:55.025147] load_flac:304 loaded libFLAC.so.8
[23:46:55.025153] register_flac:332 using flac to decode ogf,flc
[23:46:55.025159] register_pcm:483 using pcm to decode aif,pcm
[23:46:55.032636] load_mad:394 loaded libmad.so.0
[23:46:55.032684] register_mad:423 using mad to decode mp3
[23:46:55.032856] discover_server:795 sending discovery
[23:46:55.064290] discover_server:806 got response from: 192.168.50.63:3483
[23:46:55.064403] slimproto:898 connecting to 192.168.50.63:3483
[23:46:55.065673] slimproto:937 connected
[23:46:55.065722] sendHELO:148 mac: d0:c8:d9:c4:1b:64
[23:46:55.065733] sendHELO:150 cap: Model=squeezelite,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Balance=1,Firmware=v1.9.9-1386,ModelName=SqueezeLite-HA-Addon,MaxSampleRate=384000,dsf,dff,aac,ogg,ogf,flc,aif,pcm,mp3

[23:49:23.447770] decode_flush:236 decode flush
[23:49:23.447820] output_flush:445 flush output buffer
[23:49:26.567683] codec_open:264 codec open: 'm'
[23:49:26.567819] connect_socket:164 connecting to 192.168.50.63:9000
[23:49:26.570450] stream_sock:600 header: GET /stream.mp3?player=d0:c8:d9:c4:1b:64 HTTP/1.0

[23:49:26.640158] stream_thread:331 headers: len: 491
HTTP/1.1 200 OK
Server: Logitech Media Server (8.2.0 - 1627922070)
Connection: close
Content-Type: audio/mpeg
Set-Cookie: Squeezebox-albumView=; path=/
Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
Set-Cookie: Squeezebox-expanded-MY_MUSIC=0; path=/
Set-Cookie: Squeezebox-expanded-FAVORITES=0; path=/
Set-Cookie: Squeezebox-expanded-PLUGINS=0; path=/
Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=0; path=/
Set-Cookie: Squeezebox-expanded-RADIO=0; path=/

[23:49:26.686368] mad_decode:247 setting track_start
[23:49:26.686416] _checkfade:294 fade mode: 2 duration: 0 track-start
[23:49:26.686424] _checkfade:304 fade IN: 0 frames
[23:49:26.866154] _output_frames:153 track start sample rate: 44100 replay_gain: 0
[23:49:26.876382] _output_frames:181 fade start reached
[23:49:26.876432] _output_frames:214 fade complete
[23:49:28.767843] _output_frames:73 skip 26945 of 26945 frames
[23:49:30.776225] _output_frames:73 skip 79468 of 79468 frames
[23:49:33.011716] _output_frames:73 skip 94241 of 94241 frames
[23:49:35.029718] _output_frames:73 skip 76513 of 76513 frames
[23:49:37.050504] _output_frames:73 skip 88641 of 88641 frames
[23:49:39.071898] _output_frames:73 skip 72015 of 72015 frames
[23:49:41.072472] _output_frames:73 skip 80570 of 80570 frames
[23:49:43.052227] _output_frames:73 skip 79027 of 79027 frames

The only thing that fixes it is complete reboot of the device. Restarting the service does not help.

ralph-irving commented 2 years ago

I've never experienced that issue before. However, I'd suggest you try the native pulseaudio version of squeezelite instead of the alsa to see if you still hear the same noise.

xxxserxxx commented 1 year ago

I've gotten this sporadically, very rarely, in the 18 months I've been running my current set-up; recently - maybe in the past month? - it's happening (nearly) every day when I first start playing music. Restarting squeezelite fixes it; I'm about to put in a cron job to just restart squeezelite in the early AM, but that's just a hack.

Unlike OP, I do not have to reboot the device -- a simple restart of the squeezelite service does the trick.

This is running on a little ODroid ARM box with the default Ubuntu release (18.04 bionic); squeezelite is 1.8-4.1build1 armhf. I think it's just running against ALSA; the config file is sparse, setting only the instance name and the LMS server. I haven't even set the audio device; it has always worked OOB.

I don't have pulseaudio installed on this device, but I can do so. Running pulseaudio as root has always been challenging and IMO unreliable. @Vinndimon , did you try pulseaudio, and did it fix your issues?

I do notice that when I restart the process, it takes a very long time for systemd to stop and restart, and there are log messages complaining about left-over processes in the control group indicating unclean termination; this could mean the process is hanging and refusing to terminate, but I don't really know. squeezelite itself is apparently reporting no errors to the log.

What can I do to provide more debugging information?

xxxserxxx commented 1 year ago

155 looks like a related ticket, although in my case, the issue never occurs while music is (more or less) constantly playing. It only happens after there's been a period of hours when there's no streaming. Since (in my case) that's overnight, and there's a fair bit of automated system maintenance that happens in the middle of the night -- backups, etc -- and these are not beefy machines, it's possible that the LMS server is being swapped out of memory and maybe delaying a sync message; or maybe there's clock drift because of timesyncd?