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

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

Open
GoogleCodeExporter opened this issue Sep 26, 2015 · 4 comments
Open

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

GoogleCodeExporter opened this issue Sep 26, 2015 · 4 comments
Labels
auto-migrated Priority-Medium Type-Defect

Comments

@GoogleCodeExporter
Copy link 

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 [email protected] on 10 Dec 2014 at 4:32
@GoogleCodeExporter
Copy link
Author 

Sounds like a spotify plugin problem - what's in the helper app log at this 
time?

Original comment by [email protected] on 11 Dec 2014 at 9:03

@GoogleCodeExporter
Copy link
Author 

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 [email protected] on 11 Dec 2014 at 11:21

@GoogleCodeExporter
Copy link
Author 

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 [email protected] on 16 Dec 2014 at 10:39

@GoogleCodeExporter
Copy link
Author 

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 [email protected] on 17 Dec 2014 at 1:48

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

No branches or pull requests
1 participant
@GoogleCodeExporter