Hello, I hope someone can help me on this? A few days ago I registered for a Spotify Premium account for streaming music to my Squeezebox Classic. The Logitech Media Server is on my NAS (Synology DS211+). The Squeezebox and NAS are all part of my home network (wired and wireless).
The official Spotify plugin for the NAS will not work in combination with the Classic, so I installed the Third Party Spotify Plugin. So far, so good. The problem is that in the Self Test for this Plugin, I have en error on test # 4: "Streaming form Spotify Failed, check connectivity to Spotify" (Test # 1, 2 & 3 all Passed).
As far as I could check, there is no problem with the Spotify connection. Firewall rules are all OK as well.
If I cannot get around this error, I'm afraid I have to cancel my Premium account . So I hope someone has the answer!?
Results 1 to 10 of 12
-
2012-03-04, 03:20 #1Junior Member
- Join Date
- Mar 2012
- Posts
- 7
Spotify plugin failed for Self Test
-
2012-03-04, 04:08 #2Senior Member
- Join Date
- Apr 2005
- Posts
- 6,931
-
2012-03-04, 04:37 #3Junior Member
- Join Date
- Mar 2012
- Posts
- 7
Thx for the quick reply. I made a printscreen of the Helper App Logfile, see the attachment file.
-
2012-03-04, 04:57 #4Senior Member
- Join Date
- Apr 2005
- Posts
- 6,931
-
2012-03-04, 05:10 #5Junior Member
- Join Date
- Mar 2012
- Posts
- 7
Sorry, I followed your advise, this text is copied/pasted and more readable:
[10:40:13.576280] process_status:1278 process status
[10:40:13.589554] main:521 req: streamtest.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[10:40:13.591249] main:854 created teststream radio search to find track
[10:40:25.067405] main:366 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.2.2 started
[11:16:04.209495] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[11:16:04.209661] process_status:1278 process status
[11:16:12.585012] log_message:74 log: 10:16:12.584 I [ap:1766] Connecting to AP ap.spotify.com:4070
[11:16:12.595335] log_message:74 log: 10:16:12.595 I [user_cache:138] UserCache::initiateGetUsers() will query for 1 users
[11:16:12.618100] log_message:74 log: 10:16:12.618 I [ap:1224] Connected to AP: 78.31.8.51:4070
[11:16:14.077085] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[11:16:14.077207] process_status:1278 process status
[11:16:19.433616] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[11:16:19.433751] process_status:1278 process status
[11:16:19.472030] main:521 req: toplist.json res: (null) par: q=tracks&r=user prot: HTTP/1.1 auth: (null)
[11:16:19.472169] main:1105 toplist type: 2 region: 20044
[11:16:19.657962] toplist_callback:707 toplist: ok
[11:16:19.684518] metadata_updated:79 new meta
[11:16:19.699148] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[11:16:19.699261] process_status:1278 process status
[11:16:19.712088] main:521 req: streamtest.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[11:16:19.713772] main:854 created teststream radio search to find track
[11:16:24.067949] main:366 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.2.2 started
[12:16:16.245381] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[12:16:16.245547] process_status:1278 process status
[12:16:23.653093] log_message:74 log: 11:16:23.653 I [ap:1766] Connecting to AP ap.spotify.com:4070
[12:16:23.664126] log_message:74 log: 11:16:23.664 I [user_cache:138] UserCache::initiateGetUsers() will query for 1 users
[12:16:23.728280] log_message:74 log: 11:16:23.728 I [ap:1224] Connected to AP: 78.31.12.99:4070
[12:16:25.126015] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[12:16:25.126139] process_status:1278 process status
[12:16:27.997132] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[12:16:27.997269] process_status:1278 process status
[12:16:28.032140] main:521 req: toplist.json res: (null) par: q=tracks&r=user prot: HTTP/1.1 auth: (null)
[12:16:28.032285] main:1105 toplist type: 2 region: 20044
[12:16:28.373050] toplist_callback:707 toplist: ok
[12:16:28.399641] metadata_updated:79 new meta
[12:16:28.415389] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[12:16:28.415502] process_status:1278 process status
[12:16:28.428777] main:521 req: streamtest.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[12:16:28.430462] main:854 created teststream radio search to find track
[12:16:53.067182] main:366 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.2.2 started
[13:05:12.755678] main:366 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.2.2 started
[13:05:12.756492] main:386 Config: username: bram1508 cachedir: /volume1/@appstore/SqueezeCenter/Cache/spotifycache bitrate: 320 volnorm: 1 httpport: 9005 cliport: 9090
[13:05:15.778832] main:475 new connection
[13:05:15.782433] main:579 attempting login for user: bram1508
[13:05:16.194767] log_message:74 log: 12:05:16.194 I [ap:1766] Connecting to AP ap.spotify.com:4070
[13:05:16.204042] logged_in:47 logged in
[13:05:16.245701] log_message:74 log: 12:05:16.245 I [ap:1224] Connected to AP: 78.31.12.90:4070
[13:05:17.665419] main:475 new connection
[13:05:17.665571] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[13:05:17.665666] process_status:1278 process status
[13:05:19.045685] main:475 new connection
[13:05:19.048974] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[13:05:19.049098] process_status:1278 process status
[13:05:21.628688] main:475 new connection
[13:05:21.629082] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[13:05:21.629178] process_status:1278 process status
[13:05:21.642202] main:475 new connection
[13:05:21.642659] main:521 req: toplist.json res: (null) par: q=tracks&r=user prot: HTTP/1.1 auth: (null)
[13:05:21.642779] main:1105 toplist type: 2 region: 20044
[13:05:21.914335] toplist_callback:707 toplist: ok
[13:05:21.940656] metadata_updated:79 new meta
[13:05:21.954601] main:475 new connection
[13:05:21.954993] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[13:05:21.955083] process_status:1278 process status
[13:05:22.032990] main:475 new connection
[13:05:22.033512] main:521 req: streamtest.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[13:05:22.035210] main:853 streambuf_newstream: streamtest (1)
[13:05:22.035333] main:854 created teststream radio search to find track
[13:05:43.066385] main:366 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.2.2 started
[13:05:43.067185] main:386 Config: username: bram1508 cachedir: /volume1/@appstore/SqueezeCenter/Cache/spotifycache bitrate: 320 volnorm: 1 httpport: 9005 cliport: 9090
[13:06:12.135762] main:366 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.2.2 started
[13:06:43.066519] main:366 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.2.2 started
[13:08:54.955968] main:366 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.2.2 started
[13:08:54.956801] main:386 Config: username: bram1508 cachedir: /volume1/@appstore/SqueezeCenter/Cache/spotifycache bitrate: 320 volnorm: 1 httpport: 9005 cliport: 9090
[13:08:57.978897] main:475 new connection
[13:08:57.982338] main:579 attempting login for user: bram1508
[13:08:58.398647] log_message:74 log: 12:08:58.398 I [ap:1766] Connecting to AP ap.spotify.com:4070
[13:08:58.404339] logged_in:47 logged in
[13:08:58.451507] log_message:74 log: 12:08:58.451 I [ap:1224] Connected to AP: 78.31.8.42:4070
[13:08:59.413690] main:475 new connection
[13:08:59.413852] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[13:08:59.413946] process_status:1278 process status
[13:09:02.096974] main:475 new connection
[13:09:02.097382] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[13:09:02.097480] process_status:1278 process status
[13:09:02.110758] main:475 new connection
[13:09:02.111165] main:521 req: toplist.json res: (null) par: q=tracks&r=user prot: HTTP/1.1 auth: (null)
[13:09:02.111287] main:1105 toplist type: 2 region: 20044
[13:09:02.493778] toplist_callback:707 toplist: ok
[13:09:02.520258] metadata_updated:79 new meta
[13:09:02.534393] main:475 new connection
[13:09:02.534794] main:521 req: status.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[13:09:02.534886] process_status:1278 process status
[13:09:02.547466] main:475 new connection
[13:09:02.547953] main:521 req: streamtest.json res: (null) par: (null) prot: HTTP/1.1 auth: (null)
[13:09:02.549613] main:853 streambuf_newstream: streamtest (1)
[13:09:02.549740] main:854 created teststream radio search to find track
[13:09:25.066547] main:366 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.2.2 started
[13:09:25.067355] main:386 Config: username: bram1508 cachedir: /volume1/@appstore/SqueezeCenter/Cache/spotifycache bitrate: 320 volnorm: 1 httpport: 9005 cliport: 9090
-
2012-03-04, 05:15 #6Senior Member
- Join Date
- Apr 2005
- Posts
- 6,931
For some reason the helper app is restarting after every request to start a test. Can you also look in the main server log and post what this says. (You may need to set the logging level for plugin.spotify to debug to get the relavent information)
-
2012-03-04, 05:23 #7Junior Member
- Join Date
- Mar 2012
- Posts
- 7
Here's the requested dump out of the LMS server:
frame 9: (eval) (/volume1/@appstore/SqueezeCenter/Slim/Control/Request.pm line 1884)
frame 10: Slim::Control::Request::execute (/volume1/@appstore/SqueezeCenter/Slim/Web/JSONRPC.pm line 408)
frame 11: Slim::Web::JSONRPC::requestMethod (/volume1/@appstore/SqueezeCenter/Slim/Web/JSONRPC.pm line 212)
frame 12: (eval) (/volume1/@appstore/SqueezeCenter/Slim/Web/JSONRPC.pm line 212)
frame 13: Slim::Web::JSONRPC::handleURI (/volume1/@appstore/SqueezeCenter/Slim/Web/HTTP.pm line 486)
frame 14: Slim::Web::HTTP:
rocessHTTP (/volume1/@appstore/SqueezeCenter/Slim/Networking/IO/Select.pm line 139)
frame 15: (eval) (/volume1/@appstore/SqueezeCenter/Slim/Networking/IO/Select.pm line 123)
frame 16: Slim::Networking::IO::Select::__ANON__ (/volume1/@appstore/SqueezeCenter/Slim/Networking/IO/Select.pm line 184)
frame 17: (eval) (/volume1/@appstore/SqueezeCenter/Slim/Networking/IO/Select.pm line 184)
frame 18: Slim::Networking::IO::Select::loop (/volume1/@appstore/SqueezeCenter/slimserver.pl line 689)
frame 19: main::idle (/volume1/@appstore/SqueezeCenter/slimserver.pl line 645)
frame 20: main::main (/volume1/@appstore/SqueezeCenter/slimserver.pl line 1158)
[12-03-03 21:11:22.9133] Slim::Utils::Scanner::Local::rescan (171) Discovering audio files in /volume1
[12-03-03 21:11:50.5035] Slim::Utils::Scanner::Local::__ANON__ (254) Removing deleted audio files (0)
[12-03-03 21:11:50.5068] Slim::Utils::Scanner::Local::__ANON__ (332) Scanning new audio files (5541)
[12-03-03 21:11:50.5154] Slim::Utils::Scanner::Local::__ANON__ (410) Rescanning changed audio files (0)
[12-03-03 21:14:48.7838] Slim::Utils::Misc::msg (1304) Warning: [21:14:48.7819] DBI::db=HASH(0x258f2d0)->disconnect invalidates 1 active statement handle (either destroy statement handles or call finish on them before disconnecting) at /volume1/@appstore/SqueezeCenter/Slim/Schema.pm line 359.
[12-03-03 21:14:56.9537] main::init (354) Starting Logitech Media Server (v7.7.1, r33735, Mon Nov 28 16:49:58 MST 2011) perl 5.008006
[12-03-03 21:15:07.4422] Slim::Utils::Misc::msg (1304) Warning: [21:15:07.4398] Can't locate auto/IO/Interface/autosplit.ix in @INC (@INC contains: /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/lib /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8.6/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8.6/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/lib /volume1/@appstore/SqueezeCenter/CPAN /volume1/@appstore/SqueezeCenter /volume1/@appstore/SqueezeCenter /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8.6/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8.6/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/lib /volume1/@appstore/SqueezeCenter/CPAN /usr/lib/perl5/5.8.6/MARVELL_88F6281 /usr/lib/perl5/5.8.6 /usr/lib/perl5/site_perl/5.8.6/MARVELL_88F6281 /usr/lib/perl5/site_perl/5.8.6 /usr/lib/perl5/site_perl .) at /volume1/@appstore/SqueezeCenter/CPAN/AutoLoader.pm line 170.
at /volume1/@appstore/SqueezeCenter/CPAN/IO/Interface.pm line 12
[12-03-03 21:17:02.0098] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 21:17:33.0096] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 21:19:24.4504] Plugins::Spotify::ParserBase::__ANON__ (138) error http://192.168.0.102:9005/playlists.json: Timed out waiting for data
[12-03-03 21:19:24.5980] Slim::Utils::Timers::__ANON__ (273) Error: Timer Slim::Networking::Async::_async_error failed:
[12-03-03 21:20:04.0094] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 21:21:29.7032] Plugins::Spotify::ParserBase::__ANON__ (138) error http://192.168.0.102:9005/playlists.json: Timed out waiting for data
[12-03-03 21:22:35.0095] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 21:30:55.5434] Plugins::Spotify::ParserBase::__ANON__ (138) error http://192.168.0.102:9005/toplist.js...rtists&r=user: Timed out waiting for data
[12-03-03 21:31:35.3732] Plugins::Spotify::ParserBase::__ANON__ (138) error http://192.168.0.102:9005/toplist.json?q=albums&r=user: Timed out waiting for data
[12-03-03 22:36:35.0116] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 22:44:36.0021] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 22:54:11.8401] main::init (354) Starting Logitech Media Server (v7.7.1, r33735, Mon Nov 28 16:49:58 MST 2011) perl 5.008006
[12-03-03 22:54:17.6746] Slim::Utils::Misc::msg (1304) Warning: [22:54:17.6724] Can't locate auto/IO/Interface/autosplit.ix in @INC (@INC contains: /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/lib /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8.6/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8.6/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/lib /volume1/@appstore/SqueezeCenter/CPAN /volume1/@appstore/SqueezeCenter /volume1/@appstore/SqueezeCenter /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8.6/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/CPAN/arch/5.8.6/MARVELL_88F6281/auto /volume1/@appstore/SqueezeCenter/CPAN/arch/MARVELL_88F6281 /volume1/@appstore/SqueezeCenter/lib /volume1/@appstore/SqueezeCenter/CPAN /usr/lib/perl5/5.8.6/MARVELL_88F6281 /usr/lib/perl5/5.8.6 /usr/lib/perl5/site_perl/5.8.6/MARVELL_88F6281 /usr/lib/perl5/site_perl/5.8.6 /usr/lib/perl5/site_perl .) at /volume1/@appstore/SqueezeCenter/CPAN/AutoLoader.pm line 170.
at /volume1/@appstore/SqueezeCenter/CPAN/IO/Interface.pm line 12
[12-03-03 22:55:48.0033] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 22:59:13.4658] Plugins::Spotify::ParserBase::__ANON__ (138) error http://192.168.0.102:9005/playlists.json: Timed out waiting for data
[12-03-03 23:00:18.0082] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 23:00:49.0087] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 23:14:20.0090] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 23:20:21.0093] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 23:32:52.0096] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-03 23:34:23.0098] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-04 10:40:25.0073] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-04 11:16:24.0071] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-04 12:16:53.0059] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-04 13:05:43.0054] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-04 13:06:43.0055] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
[12-03-04 13:09:25.0055] Plugins::Spotify::Spotifyd::_checkAlive (135) spotifyd has failed restarting
-
2012-03-04, 06:38 #8Senior Member
- Join Date
- Apr 2005
- Posts
- 6,931
OK getting somewhere - something is cause spotifyd to crash. Are you able to ssh into the device find the location of spotifyd and run it manually with LMS stopped, then start LMS and try to redo the test. If spotifyd crashes then there should be some output to the console session saying why.
-
2012-03-04, 07:27 #9Junior Member
- Join Date
- Mar 2012
- Posts
- 7
-
2012-03-04, 08:54 #10Junior Member
- Join Date
- Mar 2012
- Posts
- 7
Alright, I did some homework and managed to get into the device by SSH using putty. I ran the commandline to activate the plugin with LMS stopped. After this, I restarted LMS and tested again. The logfile gives me the following error message: "error on bind listenfd: address already in use".
Looks like a conflict of interests?

Reply With Quote

