Announce: Spotify Premium Plugin (Beta)

[verypsb]

Can you play whole albums and only see this problems with playlists?
If so can you check if the Now Playing list things there are multiple items in the playlist (says 1 of X) or the web interface shows multiple items on the right hand panel?

Just tried an album. It only plays the first track. It looks like it doesn't advance to the next track, in albums or playlists. I will test some more...

[terjehaa]

Thanks a million Triode! This is what we all been waiting for!!!
Just a quick question; is it possible to see whether the stream from Spotify is 160 or 320kbps?

[snow]

Should not matter - what does the helper app log say when logging is set to DEBUG?

Ok - here it is:

[17:44:22.591] main:401 req: status.json res: (null) par: (null) prot: HTTP/1.0
[17:44:22.591] process_status:723 process status
[17:44:38.363] main:286 C:\PROGRA~2\SQUEEZ~1\server\Plugins\Spotify\Bin\MSWIN3~1\spotifyd.exe started
[17:44:38.363] main:304 Config: username: everlong81 cachedir: C:\ProgramData\Squeezebox\Cache\spotifycache bitrate: 320 httpport: 9001
[17:44:38.472] main:376 new connection
[17:44:38.472] main:401 req: status.json res: (null) par: login prot: HTTP/1.0
[17:44:38.472] process_status:723 process status
[17:44:38.784] main:376 new connection
[17:44:38.784] main:401 req: status.json res: (null) par: login prot: HTTP/1.0
[17:44:38.784] process_status:723 process status
[17:44:39.096] main:376 new connection
[17:44:39.096] main:401 req: status.json res: (null) par: login prot: HTTP/1.0
[17:44:39.096] process_status:723 process status
[17:44:39.408] main:376 new connection
[17:44:39.408] main:401 req: status.json res: (null) par: login prot: HTTP/1.0
[17:44:39.408] process_status:723 process status
[17:44:39.720] main:376 new connection
[17:44:39.720] main:401 req: status.json res: (null) par: login prot: HTTP/1.0
[17:44:39.720] process_status:723 process status
[17:44:40.032] main:376 new connection
[17:44:40.032] main:401 req: status.json res: (null) par: login prot: HTTP/1.0
[17:44:40.032] process_status:723 process status
[17:44:41.218] log_message:63 log: 15:44:41.218 E [proxy_resolver_win32.cpp:219] WinHttpGetProxyForUrl failed

[17:44:41.218] log_message:63 log: 15:44:41.218 I [ap:1368] Connecting to AP A1.spotify.com:4070

[17:44:42.793] container_loaded:75 playlist container loaded
[17:45:23.495] main:376 new connection
[17:45:23.511] main:401 req: playlists.json res: (null) par: (null) prot: HTTP/1.0
[17:45:23.511] process_playlists:570 process playlists
[17:45:26.818] main:376 new connection
[17:45:26.818] main:401 req: playlists.json res: spotify:user:everlong81:playlist:6y3cQTxCPzkh6nbTneyRLV par: (null) prot: HTTP/1.0
[17:45:26.818] process_singleplaylist:616 process single playlist
[17:46:36.004] main:376 new connection
[17:46:36.004] main:401 req: status.json res: (null) par: (null) prot: HTTP/1.0
[17:46:36.004] process_status:723 process status
[17:46:48.437] main:286 C:\PROGRA~2\SQUEEZ~1\server\Plugins\Spotify\Bin\MSWIN3~1\spotifyd.exe started
[17:46:50.964] log_message:63 log: 15:46:50.964 E [proxy_resolver_win32.cpp:219] WinHttpGetProxyForUrl failed

[17:46:50.964] log_message:63 log: 15:46:50.964 I [ap:1368] Connecting to AP A2.spotify.com:4070

[OppfinnarJocke]

Can you set the helper logging to DEBUG and post what the helper log shows when you try to play an album. Sounds like there is a problem advancing tracks for some reason.

Can you confirm if you play an album you get the full album appearing in the playlist of your controller (or the web front page)?

Does the FWD button move onto the next track?

Yes, I can confirm that I get the full album listed in the playlist of the controller. And it seems to play through the full album once it's started ok; "seems to" since I haven't gotten through a full album yet.

When I tried it earlier, the FWD button did move to the next track in the sense that the song info changed and SBS started counting the seconds and advancing the progress bar, but there was no audio.

And, as someone else mentioned, once a track fails playing, there seems to be no way to get it to play again. SBS counts the seconds and advances the progress bar, but no audio.

Thanks for all your help, Triode.

EDIT: No, it doesn't play the entire album through, it stopped in the middle, between two track. Manually selecting the next track gives the "silent" behavior, SBS advances the progress bar and counts the seconds, but no audio, controller says "connecting".

[Triode]

Thanks a million Triode! This is what we all been waiting for!!!
Just a quick question; is it possible to see whether the stream from Spotify is 160 or 320kbps?

I was assuming that when you select 320k they are all 320k, but if you set the helper app logging to DEBUG and look at the log you can see that this is not always true. This information is not made available anywhere other than the log.

[Triode]

Yes, I can confirm that I get the full album listed in the playlist of the controller. And it seems to play through the full album once it's started ok; "seems to" since I haven't gotten through a full album yet.

When I tried it earlier, the FWD button did move to the next track in the sense that the song info changed and SBS started counting the seconds and advancing the progress bar, but there was no audio.

And, as someone else mentioned, once a track fails playing, there seems to be no way to get it to play again. SBS counts the seconds and advances the progress bar, but no audio.

Thanks for all your help, Triode.

EDIT: No, it doesn't play the entire album through, it stopped in the middle, between two track. Manually selecting the next track gives the "silent" behavior, SBS advances the progress bar and counts the seconds, but no audio, controller says "connecting".

Can you post what the helper app logging in DEBUG settings shows when you see this?

Regarding starting a track which fails to play. Sometimes squeezeplay will remember the url you are playing and not do anything for the same url unless you press stop (press and hold pause) and then play. Does this restart it?

[Triode]

Ok - here it is:

There's still no attempts to play any tracks in that log!

Suggest you enable player.source and player.streaming.direct debugging and see what they show in the main server log.

[snow]

Ok, see anything wrong here?

http://pastebin.com/AWLh1xi4

[OppfinnarJocke]

Can you post what the helper app logging in DEBUG settings shows when you see this?

Regarding starting a track which fails to play. Sometimes squeezeplay will remember the url you are playing and not do anything for the same url unless you press stop (press and hold pause) and then play. Does this restart it?

Thing is... spotifyd.log is nowhere on my C:\, I have searched. I have set helper App Logging to Debug, and I have clicked "Apply" several times. Clicking the Log link next to it opens an empty browser window at http://127.0.0.1:9000/spotifyd.log. There should be no permission issue, I am running as an XP administrator, I have Full Control of C:\Users\All Users\Application Data\Squeezebox\Logs

Playing of failed tracks... just now the first track of an album played, and then everything paused. I pressed and held the pause button the controller, and then pressed FWD. The correct song info shows, but I get the "silent" behavior, SBS counts the seconds, the controller says "connecting".

Ooops... now the controller crashed from too much pressure on the pause button it seems... It rebooted itself, but still "silent" behavior.

EDIT: Here is my server.log from this afternoon

[10-06-19 17:04:36.6251] main::init (323) Starting Squeezebox Server (v7.5.1, r30836, Tue Jun 1 06:02:45 PDT 2010) perl 5.010000
[10-06-19 17:07:20.6095] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...5v/browse.json
Timed out waiting for data
[10-06-19 17:07:20.6255] Slim::Utils::Timers::__ANON__ (260) Error: Timer failed: illegal file descriptor or filehandle (either no attached file descriptor or illegal value): at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Networking/IO/Select.pm line 149.
[10-06-19 17:07:29.4566] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...5v/browse.json
Timed out waiting for data
[10-06-19 17:08:11.2657] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...5v/browse.json
Timed out waiting for data
[10-06-19 17:08:51.8751] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...NG/browse.json
Timed out waiting for data
[10-06-19 17:08:51.8932] Slim::Utils::Timers::__ANON__ (260) Error: Timer failed: illegal file descriptor or filehandle (either no attached file descriptor or illegal value): at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Networking/IO/Select.pm line 149.
[10-06-19 17:09:05.3438] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...NG/browse.json
Timed out waiting for data
[10-06-19 17:13:08.5470] main::init (323) Starting Squeezebox Server (v7.5.1, r30836, Tue Jun 1 06:02:45 PDT 2010) perl 5.010000
[10-06-19 18:34:47.0939] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...TG/browse.json
Timed out waiting for data
[10-06-19 18:34:47.1125] Slim::Utils::Timers::__ANON__ (260) Error: Timer failed: illegal file descriptor or filehandle (either no attached file descriptor or illegal value): at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Networking/IO/Select.pm line 149.
[10-06-19 18:34:48.2878] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...TG/browse.json
Timed out waiting for data
[10-06-19 18:34:48.3052] Slim::Utils::Timers::__ANON__ (260) Error: Timer failed: illegal file descriptor or filehandle (either no attached file descriptor or illegal value): at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Networking/IO/Select.pm line 149.
[10-06-19 18:34:53.4841] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...TG/browse.json
Timed out waiting for data
[10-06-19 18:34:53.5017] Slim::Utils::Timers::__ANON__ (260) Error: Timer failed: illegal file descriptor or filehandle (either no attached file descriptor or illegal value): at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Networking/IO/Select.pm line 149.
[10-06-19 18:35:04.5470] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...fE/browse.json
Timed out waiting for data
[10-06-19 18:35:04.5650] Slim::Utils::Timers::__ANON__ (260) Error: Timer failed: illegal file descriptor or filehandle (either no attached file descriptor or illegal value): at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Networking/IO/Select.pm line 149.
[10-06-19 18:35:27.4586] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...fE/browse.json
Timed out waiting for data
[10-06-19 18:35:27.4743] Slim::Utils::Timers::__ANON__ (260) Error: Timer failed: illegal file descriptor or filehandle (either no attached file descriptor or illegal value): at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Networking/IO/Select.pm line 149.
[10-06-19 18:35:38.7032] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...Zv/browse.json
Timed out waiting for data
[10-06-19 18:35:38.7194] Slim::Utils::Timers::__ANON__ (260) Error: Timer failed: illegal file descriptor or filehandle (either no attached file descriptor or illegal value): at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Networking/IO/Select.pm line 149.
[10-06-19 18:36:07.5939] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...hO/browse.json
Timed out waiting for data
[10-06-19 18:36:07.6100] Slim::Utils::Timers::__ANON__ (260) Error: Timer failed: illegal file descriptor or filehandle (either no attached file descriptor or illegal value): at /<C:\PROGRA~1\SQUEEZ~1\server\SQUEEZ~3.EXE>Slim/Networking/IO/Select.pm line 149.
[10-06-19 18:36:50.6095] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...TU/browse.json
Timed out waiting for data
[10-06-19 18:37:40.0626] Slim::Formats::XML::gotErrorViaHTTP (332) Error: getting http://192.168.1.7:9001/spotify:albu...wX/browse.json
Timed out waiting for data

[Triode]

Ok, see anything wrong here?

http://pastebin.com/AWLh1xi4

So the server it telling the player to connect to spotifyd, but we don't see anything in its log. Do you have any firewalls which would prevent the player connecting to port 9001 on the server machine?