kirknorthrop / squeezelite

Automatically exported from code.google.com/p/squeezelite
Other
0 stars 0 forks source link

After a certain time playing music or sitting idle (usually a few hours ~ 6 ) squeezelite stops outputting, although still responds to commands #52

Open GoogleCodeExporter opened 8 years ago

GoogleCodeExporter commented 8 years ago
What steps will reproduce the problem?
1.I start squeezelite with the following command 
   squeezelite-armv6hf  -o sysdefault:CARD=Audio -d all=debug -f var/log/squeezeslite.log

2. Either I play a long file (my test file is a 12 hour file of white noise) or 
play nothing and all squeezelite to idle

It usually takes about 6 hours either way

What is the expected output? What do you see instead?

I expect music to play - squeezelite is responsive to commands, switching 
songs, etc and appears on the remote app I am using to be playing but no sound 
comes out.

What version of the product are you using? On what operating system?

I am using 1.3 binary (squeezelite-armv6hf)
on a Raspberry Pi model B, latest distro of raspbian ( 3.10.19+ #600 )
Using a fio 10 audio DAC 

output of squeezelite-armv6hf -l
Output devices:
  null                           - Discard all samples (playback) or generate zero samples (capture)
  default:CARD=ALSA              - bcm2835 ALSA, bcm2835 ALSA - Default Audio Device
  sysdefault:CARD=ALSA           - bcm2835 ALSA, bcm2835 ALSA - Default Audio Device
  default:CARD=Audio             - DigiHug USB Audio, USB Audio - Default Audio Device
  sysdefault:CARD=Audio          - DigiHug USB Audio, USB Audio - Default Audio Device
  front:CARD=Audio,DEV=0         - DigiHug USB Audio, USB Audio - Front speakers
  surround40:CARD=Audio,DEV=0    - DigiHug USB Audio, USB Audio - 4.0 Surround output to Front and Rear speakers
  surround41:CARD=Audio,DEV=0    - DigiHug USB Audio, USB Audio - 4.1 Surround output to Front, Rear and Subwoofer speakers
  surround50:CARD=Audio,DEV=0    - DigiHug USB Audio, USB Audio - 5.0 Surround output to Front, Center and Rear speakers
  surround51:CARD=Audio,DEV=0    - DigiHug USB Audio, USB Audio - 5.1 Surround output to Front, Center, Rear and Subwoofer speakers
  surround71:CARD=Audio,DEV=0    - DigiHug USB Audio, USB Audio - 7.1 Surround output to Front, Center, Side, Rear and Woofer speakers
  iec958:CARD=Audio,DEV=0        - DigiHug USB Audio, USB Audio - IEC958 (S/PDIF) Digital Audio Output

Please provide any additional information below.
I have looked in the log file and when a file is playing it will stop when this 
occurs in the logs

09:13:35.846384] process_strm:224 strm command t
[09:13:35.846520] sendSTAT:156 STAT: STMt
[09:13:36.848169] sendSTAT:156 STAT: STMt
[09:13:37.849789] sendSTAT:156 STAT: STMt
[09:13:38.857640] sendSTAT:156 STAT: STMt
[09:13:39.847039] process:430 strm
[09:13:39.847400] process_strm:224 strm command t
[09:13:39.847584] sendSTAT:156 STAT: STMt
[09:13:40.849877] sendSTAT:156 STAT: STMt
[09:13:41.852872] sendSTAT:156 STAT: STMt
[09:13:42.855206] sendSTAT:156 STAT: STMt
[09:13:43.452157] output_thread:864 snd_pcm_delay returns: -783594
[09:13:43.507352] output_thread:864 snd_pcm_delay returns: -370993
[09:13:43.508052] output_thread:864 snd_pcm_delay returns: -370278
[09:13:43.508426] output_thread:864 snd_pcm_delay returns: -369254
[09:13:43.508897] output_thread:864 snd_pcm_delay returns: -368230
[09:13:43.509281] output_thread:864 snd_pcm_delay returns: -367206
[09:13:43.509779] output_thread:864 snd_pcm_delay returns: -366182
[09:13:43.510208] output_thread:864 snd_pcm_delay returns: -365158
[09:13:43.510623] output_thread:864 snd_pcm_delay returns: -364134
[09:13:43.511044] output_thread:864 snd_pcm_delay returns: -363110
[09:13:43.511383] output_thread:864 snd_pcm_delay returns: -362086
[09:13:43.511838] output_thread:864 snd_pcm_delay returns: -361062
[09:13:43.512220] output_thread:864 snd_pcm_delay returns: -360038
[09:13:43.512547] output_thread:864 snd_pcm_delay returns: -359014
[09:13:43.513023] output_thread:864 snd_pcm_delay returns: -357990
[09:13:43.513369] output_thread:864 snd_pcm_delay returns: -356966
[09:13:43.513852] output_thread:864 snd_pcm_delay returns: -355942
[09:13:43.514202] output_thread:864 snd_pcm_delay returns: -354918
[09:13:43.514529] output_thread:864 snd_pcm_delay returns: -353894
[09:13:43.515022] output_thread:864 snd_pcm_delay returns: -352870
[09:13:43.515365] output_thread:864 snd_pcm_delay returns: -351846
[09:13:43.515779] output_thread:864 snd_pcm_delay returns: -350822
[09:13:43.516267] output_thread:864 snd_pcm_delay returns: -350106
[09:13:43.516688] output_thread:864 snd_pcm_delay returns: -349082
[09:13:43.517104] output_thread:864 snd_pcm_delay returns: -348058
[09:13:43.517444] output_thread:864 snd_pcm_delay returns: -347034
[09:13:43.517899] output_thread:864 snd_pcm_delay returns: -346010
[09:13:43.518281] output_thread:864 snd_pcm_delay returns: -344986
[09:13:43.518659] output_thread:864 snd_pcm_delay returns: -343962
[09:13:43.519084] output_thread:864 snd_pcm_delay returns: -342938
[09:13:43.519455] output_thread:864 snd_pcm_delay returns: -341914
[09:13:43.520005] output_thread:864 snd_pcm_delay returns: -340890
[09:13:43.520382] output_thread:864 snd_pcm_delay returns: -339866
[09:13:43.520896] output_thread:864 snd_pcm_delay returns: -338842
[09:13:43.521280] output_thread:864 snd_pcm_delay returns: -337818
09:13:43.521652] output_thread:864 snd_pcm_delay returns: -336794
[09:13:43.522075] output_thread:864 snd_pcm_delay returns: -335770
[09:13:43.522412] output_thread:864 snd_pcm_delay returns: -334746
[09:13:43.522871] output_thread:864 snd_pcm_delay returns: -333722
[09:13:43.524222] output_thread:864 snd_pcm_delay returns: -333007
[09:13:43.524739] output_thread:864 snd_pcm_delay returns: -331983
[09:13:43.525166] output_thread:864 snd_pcm_delay returns: -330959
[09:13:43.525500] output_thread:864 snd_pcm_delay returns: -329935
[09:13:43.525959] output_thread:864 snd_pcm_delay returns: -328911
[09:13:43.526309] output_thread:864 snd_pcm_delay returns: -327887
[09:13:43.526905] output_thread:864 snd_pcm_delay returns: -326863
[09:13:43.527256] output_thread:864 snd_pcm_delay returns: -325839
[09:13:43.527630] output_thread:864 snd_pcm_delay returns: -324815
[09:13:43.528045] output_thread:864 snd_pcm_delay returns: -323791
[09:13:43.528411] output_thread:864 snd_pcm_delay returns: -322767
[09:13:43.528840] output_thread:864 snd_pcm_delay returns: -321743
[09:13:43.529182] output_thread:864 snd_pcm_delay returns: -320719
[09:13:43.529532] output_thread:864 snd_pcm_delay returns: -319695
[09:13:43.530173] output_thread:864 snd_pcm_delay returns: -318979
[09:13:43.530524] output_thread:864 snd_pcm_delay returns: -317955
[09:13:43.530981] output_thread:864 snd_pcm_delay returns: -316931
[09:13:43.531340] output_thread:864 snd_pcm_delay returns: -315907
[09:13:43.531742] output_thread:864 snd_pcm_delay returns: -314883

and continues until 
09:13:43.659412] output_thread:864 snd_pcm_delay returns: -6155
[09:13:43.659972] output_thread:864 snd_pcm_delay returns: -5131
[09:13:43.660349] output_thread:864 snd_pcm_delay returns: -4107
[09:13:43.660762] output_thread:864 snd_pcm_delay returns: -3083
[09:13:43.661169] output_thread:864 snd_pcm_delay returns: -2059
[09:13:43.661492] output_thread:864 snd_pcm_delay returns: -1035
[09:13:43.661932] output_thread:864 snd_pcm_delay returns: -11
[09:13:43.849549] process:430 strm
[09:13:43.850058] process_strm:224 strm command t
[09:13:43.850215] sendSTAT:156 STAT: STMt
[09:13:44.851682] sendSTAT:156 STAT: STMt
[09:13:45.853498] sendSTAT:156 STAT: STMt
[09:13:46.855279] sendSTAT:156 STAT: STMt
[09:13:47.847574] process:430 strm
[09:13:47.847833] process_strm:224 strm command t
[09:13:47.847968] sendSTAT:156 STAT: STMt
[09:13:48.850577] sendSTAT:156 STAT: STMt
[09:13:49.852177] sendSTAT:156 STAT: STMt
[09:13:50.855550] sendSTAT:156 STAT: STMt
[09:13:51.846851] process:430 strm
[09:13:51.847113] process_strm:224 strm command t
[09:13:51.847250] sendSTAT:156 STAT: STMt
[09:13:52.848885] sendSTAT:156 STAT: STMt
09:13:53.849820] sendSTAT:156 STAT: STMt
[09:13:54.851560] sendSTAT:156 STAT: STMt
[09:13:55.846584] process:430 strm
[09:13:55.846897] process_strm:224 strm command t
[09:13:55.848235] sendSTAT:156 STAT: STMt
[09:13:56.849763] sendSTAT:156 STAT: STMt
[09:13:57.852457] sendSTAT:156 STAT: STMt
[09:13:58.854057] sendSTAT:156 STAT: STMt
[09:13:59.846578] process:430 strm
[09:13:59.846834] process_strm:224 strm command t
[09:13:59.846972] sendSTAT:156 STAT: STMt
[09:14:00.848605] sendSTAT:156 STAT: STMt
[09:14:01.522985] output_thread:864 snd_pcm_delay returns: -784028
[09:14:01.578604] output_thread:864 snd_pcm_delay returns: -366903
[09:14:01.579129] output_thread:864 snd_pcm_delay returns: -365879
[09:14:01.579514] output_thread:864 snd_pcm_delay returns: -364855
[09:14:01.580125] output_thread:864 snd_pcm_delay returns: -364139
[09:14:01.580524] output_thread:864 snd_pcm_delay returns: -363115
[09:14:01.580955] output_thread:864 snd_pcm_delay returns: -362091
[09:14:01.581280] output_thread:864 snd_pcm_delay returns: -361067
[09:14:01.581716] output_thread:864 snd_pcm_delay returns: -360043
[09:14:01.582084] output_thread:864 snd_pcm_delay returns: -359019
[09:14:01.582443] output_thread:864 snd_pcm_delay returns: -357995

Here is an example when it is just sitting idly
18:48:12.351785] process_strm:224 strm command t
[18:48:12.351983] sendSTAT:156 STAT: STMt
[18:48:17.351381] process:430 strm
[18:48:17.351776] process_strm:224 strm command t
[18:48:17.351929] sendSTAT:156 STAT: STMt
[18:48:22.352638] process:430 strm
[18:48:22.352966] process_strm:224 strm command t
[18:48:22.353197] sendSTAT:156 STAT: STMt
[18:48:27.351169] process:430 strm
[18:48:27.351506] process_strm:224 strm command t
[18:48:27.351736] sendSTAT:156 STAT: STMt
[18:48:32.351250] process:430 strm
[18:48:32.351536] process_strm:224 strm command t
[18:48:32.351683] sendSTAT:156 STAT: STMt
[18:48:35.920878] output_thread:864 snd_pcm_delay returns: -783594
[18:48:35.922182] output_thread:864 snd_pcm_delay returns: -782570
[18:48:35.922725] output_thread:864 snd_pcm_delay returns: -781546
[18:48:35.923102] output_thread:864 snd_pcm_delay returns: -780522
[18:48:35.923624] output_thread:864 snd_pcm_delay returns: -779498
[18:48:35.923999] output_thread:864 snd_pcm_delay returns: -778474
[18:48:35.924390] output_thread:864 snd_pcm_delay returns: -777450

Original issue reported on code.google.com by sakap...@gmail.com on 2 Dec 2013 at 9:12

GoogleCodeExporter commented 8 years ago
Yes looks like there is a bug here.  Will look at for next version.

Original comment by trio...@btinternet.com on 4 Dec 2013 at 8:50

GoogleCodeExporter commented 8 years ago
I, too am seeing this identical problem, with a Behringer UCA-202 DAC, so my 
device string is sysdefault:CARD=CODEC

Original comment by mfpri...@gmail.com on 5 Dec 2013 at 5:46

GoogleCodeExporter commented 8 years ago
To the original poster - have you tried rpi-update?  I was having a similar 
problem and updating the Pi's firmware has eliminated the issue.

Original comment by mfpri...@gmail.com on 14 Dec 2013 at 3:18

GoogleCodeExporter commented 8 years ago
Please try the 1.4 beta version as this should change how this is handled.

Original comment by trio...@btinternet.com on 23 Dec 2013 at 10:36

GoogleCodeExporter commented 8 years ago
I suspect this is the same issue as #31 & #48. Maybe merge them? 

I am seeing the same behaviour on 1.4. You either just get silence or the odd 
pop. A restart of squeezelite solves the problem. 

I can post more logs if you like.

Original comment by morkh...@gmail.com on 6 Jan 2014 at 6:04

GoogleCodeExporter commented 8 years ago
# squeezelite -h
Squeezelite v1.4, Copyright 2012, 2013 Adrian Smith. See -t for license terms

# uname -a
Linux squeezeplug 3.10.25+ #616 PREEMPT Mon Dec 23 18:13:02 GMT 2013 armv6l 
GNU/Linux

# squeezelite -l
Output devices:
  null                           - Discard all samples (playback) or generate zero samples (capture)
  pulse                          - PulseAudio Sound Server
  sysdefault:CARD=ALSA           - bcm2835 ALSA, bcm2835 ALSA - Default Audio Device
  sysdefault:CARD=Device         - USB Sound Device, USB Audio - Default Audio Device
  front:CARD=Device,DEV=0        - USB Sound Device, USB Audio - Front speakers
  surround40:CARD=Device,DEV=0   - USB Sound Device, USB Audio - 4.0 Surround output to Front and Rear speakers
  surround41:CARD=Device,DEV=0   - USB Sound Device, USB Audio - 4.1 Surround output to Front, Rear and Subwoofer speakers
  surround50:CARD=Device,DEV=0   - USB Sound Device, USB Audio - 5.0 Surround output to Front, Center and Rear speakers
  surround51:CARD=Device,DEV=0   - USB Sound Device, USB Audio - 5.1 Surround output to Front, Center, Rear and Subwoofer speakers
  surround71:CARD=Device,DEV=0   - USB Sound Device, USB Audio - 7.1 Surround output to Front, Center, Side, Rear and Woofer speakers
  iec958:CARD=Device,DEV=0       - USB Sound Device, USB Audio - IEC958 (S/PDIF) Digital Audio Output

Execution Flags
SLOPTIONS="-n Study -o sysdefault:CARD=Device -d all=debug -f 
/var/log/squeezelite.log -p 2 -a 100:4 192.168.1.11"

Some comments on the log:
Last night at 21:52:57.118329 the last track ended.
This morning at 06:45:37.552011 I started playback. Again just silence with the 
odd pop.
At 06:46:23.740098 I restarted squeezelite and playback resumed without any 
further intervention.

Full log is attached. 

Original comment by morkh...@gmail.com on 7 Jan 2014 at 5:32

Attachments:

GoogleCodeExporter commented 8 years ago
Can't see anything specific in that log.  Could you try with -d output=sdebug 
to see if there's anything strange there (you will get lots more output)

This does seem to be specific to the Pi though?

Original comment by trio...@btinternet.com on 7 Jan 2014 at 9:16

GoogleCodeExporter commented 8 years ago
I will change the logging tonight and see what it looks like in the morning.

I will also fire up a client on my Windows machine at the same time so we can 
see if it's only a Pi thing.

Original comment by morkh...@gmail.com on 8 Jan 2014 at 4:50

GoogleCodeExporter commented 8 years ago
Experiment all setup and of course this morning it all just works. Both the Pi 
and Windows machine play. The one thing I did change was selecting an album 
encoded in FLAC because I recall you mentioning somewhere that libmad may have 
issues. So I will repeat this test again with an MP3 encoded album.

Original comment by morkh...@gmail.com on 9 Jan 2014 at 4:37

GoogleCodeExporter commented 8 years ago
If it turns out to be libmad then try mpg123 as an mp3 codec - there are some 
arm builds on libmad which cased segfaults, but I am not aware of ones which 
stop working after a while...

Original comment by trio...@btinternet.com on 9 Jan 2014 at 9:23

GoogleCodeExporter commented 8 years ago
As Murphy would have it I haven't been able to reproduce this with sdebug on. 
I'll carry on testing till I get it to fail again and report back.

Original comment by morkh...@gmail.com on 10 Jan 2014 at 4:32

GoogleCodeExporter commented 8 years ago
I have a bit of a strange problem. When I run squeezelite with sdebug on I 
can't reproduce the problem. As soon as I go back to all=debug the problem 
comes back again. It's almost as if sdebug is keeping squeezelite "alive". 
Possible fix except for the log size problem ;)

So I changed tactics and decided to give mpg123 a go, but I'm struggling with 
rates which mpg seems to be very fussy about. My USB card does up to 48000.

With mad set, playback works and I see this in the logs:
[01:09:33.791373] output_init_alsa:623 init output
[01:09:33.792589] output_init_alsa:645 requested alsa_buffer: 100 alsa_period: 
4 format: any mmap: 1
[01:09:33.792887] output_init_common:318 outputbuf size: 3528000
[01:09:33.885870] output_init_common:378 supported rates: 96000 48000 44100
[01:09:33.919386] output_init_alsa:657 memory locked
[01:09:33.920593] output_thread:465 open output device: hw:CARD=Device
[01:09:33.923055] alsa_open:234 opened device hw:CARD=Device using format: 
S16_LE sample rate: 44100 mmap: 1
[01:09:33.923640] alsa_open:313 buffer: 100 period: 4 -> buffer size: 4412 
period size: 1103
[01:09:33.924124] output_init_alsa:680 set output sched fifo rt: 2
Hardware PCM card 1 'USB Sound Device' device 0 subdevice 0
Its setup is:
  stream       : PLAYBACK
  access       : MMAP_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 4412
  period_size  : 1103
  period_time  : 25011
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 1103
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 4412
  silence_threshold: 0
  silence_size : 0
  boundary     : 1156579328
  appl_ptr     : 0
  hw_ptr       : 0
[01:09:33.927861] _output_frames:111 avail: 4412 frames: 2048 silence: 1

With mpg set, playback does not work and I see complaints of not being able to 
set output formats:
[01:11:16.637386] output_init_alsa:623 init output
[01:11:16.639019] output_init_alsa:645 requested alsa_buffer: 100 alsa_period: 
4 format: any mmap: 1
[01:11:16.639398] output_init_common:318 outputbuf size: 3528000
[01:11:16.730571] output_init_common:378 supported rates: 96000 48000 44100
[01:11:16.762777] output_init_alsa:657 memory locked
[01:11:16.763965] output_thread:465 open output device: hw:CARD=Device
[01:11:16.766422] alsa_open:234 opened device hw:CARD=Device using format: 
S16_LE sample rate: 44100 mmap: 1
[01:11:16.767027] alsa_open:313 buffer: 100 period: 4 -> buffer size: 4412 
period size: 1103
[01:11:16.767517] output_init_alsa:680 set output sched fifo rt: 2
Hardware PCM card 1 'USB Sound Device' device 0 subdevice 0
Its setup is:
  stream       : PLAYBACK
  access       : MMAP_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 4412
  period_size  : 1103
  period_time  : 25011
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 1103
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 4412
  silence_threshold: 0
  silence_size : 0
  boundary     : 1156579328
  appl_ptr     : 0
  hw_ptr       : 0
[01:11:16.771415] _output_frames:111 avail: 4412 frames: 2048 silence: 1
[SNIP]
[01:11:17.080043] _output_frames:245 wrote 926 frames
[format.c:269] error: Unable to set up output format! Constraints: 44100, 22050 
or 11025Hz.
[01:11:17.100911] mpg_decode:173 Error

I've had a go at setting rates with -r, but either there is some other issue or 
my syntax is incorrect as my alsa breaks and I have to reboot before aplay -l 
and squeezelite -l will show any cards again.

Only output I get is:
# squeezelite -l
Bus error

Original comment by morkh...@gmail.com on 11 Jan 2014 at 11:17

GoogleCodeExporter commented 8 years ago
Can you shown what all parameters are you are starting with?

Original comment by trio...@btinternet.com on 11 Jan 2014 at 11:23

GoogleCodeExporter commented 8 years ago
This is what is working with mad
-n Study -o hw:CARD=Device -c mad,flac -d all=debug -f /var/log/squeezelite.log 
-p 2 -a 100:4 192.168.1.11

I tried: 
-n Study -o hw:CARD=Device -r 44100 -c mad,flac -d all=debug -f 
/var/log/squeezelite.log -p 2 -a 100:4 192.168.1.11
Which breaks alsa

Original comment by morkh...@gmail.com on 12 Jan 2014 at 12:09

GoogleCodeExporter commented 8 years ago
note you need -s before the ip address with recent versions.  If you set -r 
44100 and the material is not 44100 then you will have a problem - what are you 
playing?

Original comment by trio...@btinternet.com on 12 Jan 2014 at 12:17

GoogleCodeExporter commented 8 years ago
Thanks will amend my flags to include the -s

Just playing bog standard CD rips either in "decent" quality mp3 or FLAC. The 
material certainly is 44100.

I ended with a FLAC album last night and this morning it played again with no 
intervention. I'm going to stick with FLAC and the all=debug for the next few 
days and will report back. If that works consistently I'll go back to battling 
with mpg123. I did come across this detailed article late last night which 
looks like it might solve my sampling issues, but it was a bit much for my 
tired brain at that point :p 
http://pieces.openpolitics.com/2013/05/pogoplayer-alsa/

Original comment by morkh...@gmail.com on 12 Jan 2014 at 10:18

GoogleCodeExporter commented 8 years ago
[deleted comment]
GoogleCodeExporter commented 8 years ago
I've been sticking to just FLAC for the last few days and so far no issues. So 
it would seem to me there is an issue with Pi, Squeezelite and mad. Triode are 
you able to reproduce this?

Will see if I have some time over the weekend to have another go at mpg123.

Original comment by morkh...@gmail.com on 15 Jan 2014 at 4:32

GoogleCodeExporter commented 8 years ago
[deleted comment]
GoogleCodeExporter commented 8 years ago
squeezelite uses libmad or libmpg123 - so you will libmpg123 rather than lame 
to get the alternative codec

Original comment by trio...@btinternet.com on 28 Jan 2014 at 8:55