search

jjalling / squeezelite

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

squeezelite 1.6.5 and LMS Spotify plugin 2.3.9. Intermittent stops. No recovery until squeezelite player restarted. #80

Open GoogleCodeExporter opened 8 years ago

GoogleCodeExporter commented 8 years ago 
What steps will reproduce the problem?

1.Play the Spotify Premium Account (320k) using LMS 2.3.9 plugin and 
squeezelite 1.6.5
at some point the playback from Spotify will stop. The LMS UI will still show 
the track info, skipping song will change the track info but the play-bar will 
skip to the end of song after 2 seconds. No other services will produce the 
sound via squeezelite (Pandora, local Radio stations). 
Some times it takes up to 3 days to see the fault. Sometime it can happen 
several times a day (network quality accessing Spotify?) 

There is nothing unusual in the squeezelite debug log.

spotify.d log   the playback stopped around 15:49-53
15:53-54 trying to skip songs

---
[15:48:22.928431] main:1620 Now playing: Pink Moon
[15:48:23.372245] music_delivery:485 channels: 2 sample rate: 44100 streaming 
as: PCM
[15:48:28.407046] log_message:81 log: 02:48:28.406 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:30.915396] log_message:81 log: 02:48:30.915 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:33.353128] log_message:81 log: 02:48:33.353 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:41.128476] log_message:81 log: 02:48:41.128 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:49.821341] log_message:81 log: 02:48:49.821 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:57.844154] log_message:81 log: 02:48:57.844 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:49:07.282087] log_message:81 log: 02:49:07.282 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:49:19.539089] log_message:81 log: 02:49:19.539 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:49:31.698300] log_message:81 log: 02:49:31.698 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:49:55.009359] main:567 new connection
[15:49:55.014103] main:619 req: prefetch.json res: 
spotify:track:567EmmCbOtpEuaVC2zznU6 par: (null) prot: HTTP/1.0 auth: (null)
[15:49:55.014818] main:985 prefetching track: No error
[15:49:59.432556] log_message:81 log: 02:49:59.432 I 
[file_streamer_simple.cpp:769] Request for file 
c80535e3ebd58bd2107afa2b682667b8016b567b complete (code: 0)
[15:53:06.859106] main:567 new connection
[15:53:06.891781] main:619 req: stream.pcm res: 
spotify:track:567EmmCbOtpEuaVC2zznU6 par: 
player=00%3A01%3Ac0%3A15%3Aa4%3A81&start=0&sync=1&id=428 prot: SPOTSTREAM/1.0 
auth: (null)
[15:53:06.891983] main:813 newstream connection from 127.0.0.1
[15:53:06.892030] main:849 streamid: 427 newid: 428 type: PCM
[15:53:06.892066] main:853 existing streaming connection exists - killing
[15:53:06.892456] main:886 streambuf_newstream
[15:53:06.892528] set_sndbuf:227 setsockopt: asked for 524288 got 1048576
[15:53:06.892571] main:1620 Now playing: Dirty Old Town
[15:53:06.893486] log_message:81 log: 02:53:06.893 I [social_presence.cpp:135] 
Presence: A track was played
[15:53:07.386585] music_delivery:485 channels: 2 sample rate: 44100 streaming 
as: PCM
[15:53:10.805029] log_message:81 log: 02:53:10.804 I 
[file_streamer_simple.cpp:769] Request for file 
dfd6ea1d3083a06fbecac6c8fb9dda535594019b complete (code: 0)
[15:53:12.819064] log_message:81 log: 02:53:12.819 I 
[file_streamer_simple.cpp:769] Request for file 
dfd6ea1d3083a06fbecac6c8fb9dda535594019b complete (code: 0)
[15:53:16.497426] log_message:81 log: 02:53:16.497 I 
[file_streamer_simple.cpp:769] Request for file 
dfd6ea1d3083a06fbecac6c8fb9dda535594019b complete (code: 0)
[15:53:25.560661] log_message:81 log: 02:53:25.560 I 
[file_streamer_simple.cpp:769] Request for file 
dfd6ea1d3083a06fbecac6c8fb9dda535594019b complete (code: 0)
[15:54:03.167767] music_delivery:571 error writing
[15:54:03.168500] main:1603 resetting streambuf
[15:56:42.008534] main:567 new connection
[15:56:42.013327] main:619 req: prefetch.json res: 
spotify:track:5FiApxXEFHcStt784oxv1x par: (null) prot: HTTP/1.0 auth: (null)
[15:56:42.013637] main:985 prefetching track: No error
-----

What version of the product are you using? On what operating system?
1.6.5 on debian 7.6 armv7l. LMS 7.7.5 Spotify plugin 2.3.9

The only way to recover the playback is to restart the squeezelite player.
Suspect some sort of buffering(network) issue from which squeezelite cannot 
recover untill a restart. 
Tried to manipulate some of the sysctl values on the system - no result.
Playback of Pandora or Local Radio have proved weeks of playback without a 
single issue.

What direction would you recommend to take in further troubleshooting?
Thanks in advance

Original issue reported on code.google.com by ginzburg...@gmail.com on 10 Dec 2014 at 4:32

GoogleCodeExporter commented 8 years ago 
Sounds like a spotify plugin problem - what's in the helper app log at this 
time?

Original comment by trio...@btinternet.com on 11 Dec 2014 at 9:03

GoogleCodeExporter commented 8 years ago 
you mean /var/log/squeezeboxserver/spotifyd.log  ?

-----
spotify.d log   the playback stopped around 15:49-53
15:53-54 trying to skip songs

---
[15:48:22.928431] main:1620 Now playing: Pink Moon
[15:48:23.372245] music_delivery:485 channels: 2 sample rate: 44100 streaming 
as: PCM
[15:48:28.407046] log_message:81 log: 02:48:28.406 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:30.915396] log_message:81 log: 02:48:30.915 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:33.353128] log_message:81 log: 02:48:33.353 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:41.128476] log_message:81 log: 02:48:41.128 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:49.821341] log_message:81 log: 02:48:49.821 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:48:57.844154] log_message:81 log: 02:48:57.844 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:49:07.282087] log_message:81 log: 02:49:07.282 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:49:19.539089] log_message:81 log: 02:49:19.539 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:49:31.698300] log_message:81 log: 02:49:31.698 I 
[file_streamer_simple.cpp:769] Request for file 
31d05bc20efdc6b16579d36af91320f20a66740a complete (code: 0)
[15:49:55.009359] main:567 new connection
[15:49:55.014103] main:619 req: prefetch.json res: 
spotify:track:567EmmCbOtpEuaVC2zznU6 par: (null) prot: HTTP/1.0 auth: (null)
[15:49:55.014818] main:985 prefetching track: No error
[15:49:59.432556] log_message:81 log: 02:49:59.432 I 
[file_streamer_simple.cpp:769] Request for file 
c80535e3ebd58bd2107afa2b682667b8016b567b complete (code: 0)
[15:53:06.859106] main:567 new connection
[15:53:06.891781] main:619 req: stream.pcm res: 
spotify:track:567EmmCbOtpEuaVC2zznU6 par: 
player=00%3A01%3Ac0%3A15%3Aa4%3A81&start=0&sync=1&id=428 prot: SPOTSTREAM/1.0 
auth: (null)
[15:53:06.891983] main:813 newstream connection from 127.0.0.1
[15:53:06.892030] main:849 streamid: 427 newid: 428 type: PCM
[15:53:06.892066] main:853 existing streaming connection exists - killing
[15:53:06.892456] main:886 streambuf_newstream
[15:53:06.892528] set_sndbuf:227 setsockopt: asked for 524288 got 1048576
[15:53:06.892571] main:1620 Now playing: Dirty Old Town
[15:53:06.893486] log_message:81 log: 02:53:06.893 I [social_presence.cpp:135] 
Presence: A track was played
[15:53:07.386585] music_delivery:485 channels: 2 sample rate: 44100 streaming 
as: PCM
[15:53:10.805029] log_message:81 log: 02:53:10.804 I 
[file_streamer_simple.cpp:769] Request for file 
dfd6ea1d3083a06fbecac6c8fb9dda535594019b complete (code: 0)
[15:53:12.819064] log_message:81 log: 02:53:12.819 I 
[file_streamer_simple.cpp:769] Request for file 
dfd6ea1d3083a06fbecac6c8fb9dda535594019b complete (code: 0)
[15:53:16.497426] log_message:81 log: 02:53:16.497 I 
[file_streamer_simple.cpp:769] Request for file 
dfd6ea1d3083a06fbecac6c8fb9dda535594019b complete (code: 0)
[15:53:25.560661] log_message:81 log: 02:53:25.560 I 
[file_streamer_simple.cpp:769] Request for file 
dfd6ea1d3083a06fbecac6c8fb9dda535594019b complete (code: 0)
[15:54:03.167767] music_delivery:571 error writing
[15:54:03.168500] main:1603 resetting streambuf
[15:56:42.008534] main:567 new connection
[15:56:42.013327] main:619 req: prefetch.json res: 
spotify:track:5FiApxXEFHcStt784oxv1x par: (null) prot: HTTP/1.0 auth: (null)
[15:56:42.013637] main:985 prefetching track: No error
-----

Original comment by ginzburg...@gmail.com on 11 Dec 2014 at 11:21

GoogleCodeExporter commented 8 years ago 
Just stopped once again. 11:32:39

---
[11:32:39.398930] log_message:81 log: 22:32:39.398 I 
[file_streamer_simple.cpp:769] Request for file 
cce5fe73cb2778edd5ba7074d1cfac917ff0ca2b complete (code: 0)
[11:33:12.988926] music_delivery:571 error writing
[11:33:12.989473] main:1603 resetting streambuf
[11:33:13.007361] main:567 new connection
[11:33:13.095191] main:619 req: stream.pcm res: 
spotify:track:131l86qi6735S0m8LFkpBK par: 
player=00%3A01%3Ac0%3A15%3Aa4%3A81&start=0&sync=1&id=378 prot: SPOTSTREAM/1.0 
auth: (null)
[11:33:13.095542] main:813 newstream connection from 127.0.0.1
[11:33:13.095648] main:849 streamid: 0 newid: 378 type: PCM
[11:33:13.095734] main:886 streambuf_newstream
[11:33:13.095828] set_sndbuf:227 setsockopt: asked for 524288 got 1048576
[11:33:13.095918] main:1620 Now playing: Stay High - Habits Remix
[11:33:13.097173] log_message:81 log: 22:33:13.097 I [social_presence.cpp:135] 
Presence: A track was played
[11:33:13.597636] music_delivery:485 channels: 2 sample rate: 44100 streaming 
as: PCM
[11:33:16.727858] log_message:81 log: 22:33:16.727 I 
[file_streamer_simple.cpp:769] Request for file 
1448778f6128a183351628595437458602fac31f complete (code: 0)
[11:33:18.717996] log_message:81 log: 22:33:18.717 I 
[file_streamer_simple.cpp:769] Request for file 
1448778f6128a183351628595437458602fac31f complete (code: 0)
[11:33:21.415017] music_delivery:571 error writing
[11:33:21.428586] main:1603 resetting streambuf

Original comment by ginzburg...@gmail.com on 16 Dec 2014 at 10:39

GoogleCodeExporter commented 8 years ago 
And it stopped once again. It looks like Internet connections today a bit laggy 
- might be a reasons for the fault.
I guess music_delivery:571 error writing  that is the sign of the fault 

---
[14:40:18.014872] main:567 new connection
[14:40:18.025386] main:619 req: prefetch.json res: 
spotify:track:13P5rwmk2EsoFRIz9UCeh9 par: (null) prot: HTTP/1.0 auth: (null)
[14:40:18.025942] main:985 prefetching track: No error
[14:40:20.953478] log_message:81 log: 01:40:20.953 I 
[file_streamer_simple.cpp:769] Request for file 
1b7fa50339158f72db3bdc120cb722dc0d776ac7 complete (code: 0)
[14:40:46.789578] music_delivery:571 error writing
[14:40:46.790287] main:1603 resetting streambuf
[14:40:46.814769] main:567 new connection

-------

Original comment by ginzburg...@gmail.com on 17 Dec 2014 at 1:48