[Announce] Spotty 4.0 - integrate local library with your Spotify collection (LMS 8+)

[mherger]

As I said I can resolve the issue by manually copying the MSWin32-x86-multi-thread version of spotty to the Bin folder. So I was thinking that there may be an issue with plugin.pm looking for a 64 bit version of Spotty.

Hold on... are you saying that copying the file from the MSWin32-x86-multi-thread sub folder one level up would get things working?!?

[foxesden]

Hold on... are you saying that copying the file from the MSWin32-x86-multi-thread sub folder one level up would get things working?!?

Yes, that is correct.

[mherger]

Could you please enable logging for plugin.spotty and os.paths _without_ that additional copy of spotty.exe. Then see what server.log says when you try to authenticate or navigate Spotify content?

Also: what would the path for helpers be, as reported in Settings/Information?

[foxesden]

The helper path is this
E:\GitHub\slimserver-win64\Bin\MSWin32-x64-multi-thread, E:\GitHub\slimserver-win64\Bin, C:\work\StrawberryPerl\perl\bin, C:\ProgramData\Squeezebox\Cache\InstalledPlugins\P lugins\C3PO\Bin, C:\ProgramData\Squeezebox\Cache\InstalledPlugins\P lugins\Spotty\Bin, C:\ProgramData\Squeezebox\Cache\InstalledPlugins\P lugins\SqueezeDSP\Bin, C:\ProgramData\Squeezebox\Cache\InstalledPlugins\P lugins\UPnPBridge\Bin

NB this is a build that I am using for writing my DSP plugin, hence may be non-standard.

So when I remove the spotty helper and reboot the server with debug logging enabled for spotty I get multiple entries like this

[23-02-07 14:45:30.2498] Plugins::Spotty::API::Token::get (226) Didn't find cached token. Need to refresh.
[23-02-07 14:45:30.2499] Plugins::Spotty::API::Token::get (257) Can't do non-blocking getToken call. Good luck!
[23-02-07 14:45:30.3182] Plugins::Spotty::Helper::get (51) Didn't find Spotty helper application!
[23-02-07 14:45:30.3183] Plugins::Spotty::API::Token::_logCommand (155) Trying to get access token: "" -n "Squeezebox" -c "C:\ProgramData\Squeezebox\Cache\spotty\70a51b 7b" -i "93aac68fb06348598c1e67734dfaceee" --disable-discovery --get-token --scope "user-read-private,user-follow-modify,user-follow-read,user-library-read,user-library-modify,user-top-read,user-read-recently-played,user-read-playback-state,user-modify-playback-state,playlist-read-private,playlist-read-collaborative,playlist-modify-public,playlist-modify-private"
[23-02-07 14:45:30.3490] Slim::Control::Request::execute (1888) Error: While trying to run function coderef [Slim::Control::Queries::cursonginfoQuery]: [Can't use string ("foxesden") as a HASH ref while "strict refs" in use at C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/API/Token.pm line 163.

]
[23-02-07 14:45:30.3491] Slim::Web::JSONRPC::requestMethod (477) Request failed with error: Bad dispatch!
[23-02-07 14:45:30.3512] Plugins::Spotty::API::Token::get (226) Didn't find cached token. Need to refresh.

Then when I try and access the plugins settings page

[23-02-07 14:46:14.4880] Plugins::Spotty::AccountHelper::renameCacheFolder (147) Trying to rename __AUTHENTICATE__ to
[23-02-07 14:46:14.4881] Plugins::Spotty::AccountHelper::renameCacheFolder (149) Error: No newId found in '__AUTHENTICATE__'
[23-02-07 14:46:14.4882] Plugins::Spotty::AccountHelper::renameCacheFolder (149) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/AccountHelper.pm line 149)
frame 1: Plugins::Spotty::AccountHelper::renameCacheFolder (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 187)
frame 2: Plugins::Spotty::Settings::Auth::cleanup (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/Settings.pm line 61)
frame 3: Plugins::Spotty::Settings::handler (E:/GitHub/slimserver-win64/Slim/Web/HTTP.pm line 1171)
frame 4: Slim::Web::HTTP::generateHTTPResponse (E:/GitHub/slimserver-win64/Slim/Web/HTTP.pm line 933)
frame 5: Slim::Web::HTTP:rocessURL (E:/GitHub/slimserver-win64/Slim/Web/HTTP.pm line 728)
frame 6: Slim::Web::HTTP:rocessHTTP (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 122)
frame 7: (eval) (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 118)
frame 8: Slim::Networking::IO::Select::__ANON__ (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 167)
frame 9: (eval) (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 167)
frame 10: Slim::Networking::IO::Select::loop (slimserver.pl line 734)
frame 11: main::idle (slimserver.pl line 684)
frame 12: main::main (slimserver.pl line 1228)

[23-02-07 14:46:14.4888] Plugins::Spotty::AccountHelper::renameCacheFolder (147) Trying to rename __AUTHENTICATE__ to
[23-02-07 14:46:14.4889] Plugins::Spotty::AccountHelper::renameCacheFolder (149) Error: No newId found in '__AUTHENTICATE__'
[23-02-07 14:46:14.4890] Plugins::Spotty::AccountHelper::renameCacheFolder (149) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/AccountHelper.pm line 149)
frame 1: Plugins::Spotty::AccountHelper::renameCacheFolder (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 187)
frame 2: Plugins::Spotty::Settings::Auth::cleanup (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 197)
frame 3: Plugins::Spotty::Settings::Auth::shutdownHelper (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/Settings.pm line 143)
frame 4: Plugins::Spotty::Settings::handler (E:/GitHub/slimserver-win64/Slim/Web/HTTP.pm line 1171)
frame 5: Slim::Web::HTTP::generateHTTPResponse (E:/GitHub/slimserver-win64/Slim/Web/HTTP.pm line 933)
frame 6: Slim::Web::HTTP:rocessURL (E:/GitHub/slimserver-win64/Slim/Web/HTTP.pm line 728)
frame 7: Slim::Web::HTTP:rocessHTTP (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 122)
frame 8: (eval) (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 118)
frame 9: Slim::Networking::IO::Select::__ANON__ (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 167)
frame 10: (eval) (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 167)
frame 11: Slim::Networking::IO::Select::loop (slimserver.pl line 734)
frame 12: main::idle (slimserver.pl line 684)
frame 13: main::main (slimserver.pl line 1228)

[23-02-07 14:46:14.6358] Plugins::Spotty::Helper::get (51) Didn't find Spotty helper application!
[23-02-07 14:46:14.7114] Plugins::Spotty::Helper::get (51) Didn't find Spotty helper application!
[23-02-07 14:46:14.7115] Plugins::Spotty::Connect::canSpotifyConnect (85) Cannot support Spotty Connect, need at least helper version 0.12.0
[23-02-07 14:46:15.3647] Plugins::Spotty::API::Token::get (226) Didn't find cached token. Need to refresh.
[23-02-07 14:46:15.3648] Plugins::Spotty::API::Token::get (257) Can't do non-blocking getToken call. Good luck!
[23-02-07 14:46:15.4627] Plugins::Spotty::Helper::get (51) Didn't find Spotty helper application!
[23-02-07 14:46:15.4628] Plugins::Spotty::API::Token::_logCommand (155) Trying to get access token: "" -n "Squeezebox" -c "C:\ProgramData\Squeezebox\Cache\spotty\70a51b 7b" -i "93aac68fb06348598c1e67734dfaceee" --disable-discovery --get-token --scope "user-read-private,user-follow-modify,user-follow-read,user-library-read,user-library-modify,user-top-read,user-read-recently-played,user-read-playback-state,user-modify-playback-state,playlist-read-private,playlist-read-collaborative,playlist-modify-public,playlist-modify-private"
[23-02-07 14:46:15.4753] Slim::Control::Request::execute (1888) Error: While trying to run function coderef [Plugins::UPnPBridge::Plugin::statusQuery]: [Can't use string ("foxesden") as a HASH ref while "strict refs" in use at C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/API/Token.pm line 163.

[foxesden]

Oh - earlier in the log~:

23-02-07 14:45:21.1704] Plugins::Spotty::ProtocolHandler::getMetadataFor (181) Returning metadata cached in song object for spotify:track:7vQH2Jm0b0RGl0hGzXVLdG
[23-02-07 14:45:21.1706] Plugins::Spotty::ProtocolHandler::getMetadataFor (182) {
album => "Electrified",
artist => "Boris Blank",
bitrate => "320k VBR",
cover => "https://i.scdn.co/image/ab67616d0000b2738346670dbecc4809a85e5c9e",
duration => "206.506",
icon => "/html/images/cover.png",
originalType => "Ogg Vorbis (Spotify)",
title => "Cult Of Mirrors",
type => "Ogg Vorbis (Spotify)",
url => "spotify:track:7vQH2Jm0b0RGl0hGzXVLdG",
}
[23-02-07 14:45:22.1846] Slim::bootstrap::sigint (403) Got sigint
[23-02-07 14:45:22.1860] Slim::Utils::PluginManager::shutdownPlugins (410) Shutting down plugins...
[23-02-07 14:45:22.1865] Plugins::Spotty::AccountHelper:urgeAudioCache (249) Starting temporary file cleanup... (C:\Users\jonat\AppData\Local\Temp - uid: 0)
[23-02-07 14:45:22.1908] Plugins::Spotty::AccountHelper:urgeAudioCache (270) Audio cache cleanup done!
[23-02-07 14:45:22.1911] Plugins::Spotty::AccountHelper::renameCacheFolder (147) Trying to rename __AUTHENTICATE__ to
[23-02-07 14:45:22.1912] Plugins::Spotty::AccountHelper::renameCacheFolder (149) Error: No newId found in '__AUTHENTICATE__'
[23-02-07 14:45:22.1913] Plugins::Spotty::AccountHelper::renameCacheFolder (149) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/AccountHelper.pm line 149)
frame 1: Plugins::Spotty::AccountHelper::renameCacheFolder (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 187)
frame 2: Plugins::Spotty::Settings::Auth::cleanup (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 197)
frame 3: Plugins::Spotty::Settings::Auth::shutdownHelper (C:\ProgramData\Squeezebox\Cache\InstalledPlugins/Plugins/Spotty/Plugin.pm line 325)
frame 4: Plugins::Spotty::Plugin::shutdownPlugin (E:/GitHub/slimserver-win64/Slim/Utils/PluginManager.pm line 416)
frame 5: (eval) (E:/GitHub/slimserver-win64/Slim/Utils/PluginManager.pm line 416)
frame 6: Slim::Utils::PluginManager::shutdownPlugins (slimserver.pl line 1192)
frame 7: main::cleanup (E:/GitHub/slimserver-win64/Slim/bootstrap.pm line 407)
frame 8: Slim::bootstrap::sigint (E:/GitHub/slimserver-win64/Slim/Utils/Timers.pm line 256)
frame 9: (eval) (E:/GitHub/slimserver-win64/Slim/Utils/Timers.pm line 256)
frame 10: Slim::Utils::Timers::__ANON__ (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 167)
frame 11: (eval) (E:/GitHub/slimserver-win64/Slim/Networking/IO/Select.pm line 167)
frame 12: Slim::Networking::IO::Select::loop (slimserver.pl line 734)
frame 13: main::idle (slimserver.pl line 684)
frame 14: main::main (slimserver.pl line 1228)

[23-02-07 14:45:22.1925] Slim::bootstrap::theEND (439) Got to the END
[23-02-07 14:45:25.2354] main::init (390) Starting Logitech Media Server (v8.3.0, TRUNK, UNKNOWN) perl 5.032001 - MSWin32-x64-multi-thread
[23-02-07 14:45:25.2413] main::init (420) OS Specific init...
[23-02-07 14:45:25.2414] main::init (488) Server binary search path init...
[23-02-07 14:45:25.2707] main::init (492) Server PluginManager init...
[23-02-07 14:45:25.2733] Slim::Utils::PluginDownloader::init (46) downloading to C:\ProgramData\Squeezebox\Cache\DownloadedPlugins
[23-02-07 14:45:25.2734] Slim::Utils::PluginDownloader::init (47) extracting to C:\ProgramData\Squeezebox\Cache\InstalledPlugins
[23-02-07 14:45:25.2736] Slim::Utils::PluginManager::_loadPluginCache (610) Loading plugin cache file.
[23-02-07 14:45:25.2758] Slim::Utils::PluginManager::_loadPluginCache (619) Cache Info: {
bin => "E:/GitHub/slimserver-win64",
count => 58,
mtimesum => "96130474733",
osArch => 8664,
osType => "Windows",
revision => "TRUNK",
server => "8.3.0",
version => 4,


followed some time later by
23-02-07 14:45:26.6545] Plugins::Spotty::OPML::init (126) Successfully registered BrowseArtist handler for Spotify
[23-02-07 14:45:26.7246] Plugins::Spotty::Helper::get (51) Didn't find Spotty helper application!
[23-02-07 14:45:26.7247] Plugins::Spotty::Connect::canSpotifyConnect (85) Cannot support Spotty Connect, need at least helper version 0.12.0
[23-02-07 14:45:26.7962] Plugins::Spotty::Helper::get (51) Didn't find Spotty helper application!
[23-02-07 14:45:26.7963] Plugins::Spotty::Plugin::updateTranscodingTable (270) [spotty] -n Squeezebox -c "C:\ProgramData\Squeezebox\Cache\spotty\70a51b 7b" --single-track $FILE$ --disable-discovery --disable-audio-cache $START$ | [sox] -q -t raw -b 16 -e signed -c 2 -r 44.1k -L - -t wav - | [SqueezeDSP] --id="d0:50:99:85:19:e9" --wav=true --wavo=true --d=24 | [flac] -cs -0 --totally-silent --ignore-chunk-sizes -
[23-02-07 14:45:26.7964] Plugins::Spotty::Plugin::updateTranscodingTable (270) [spotty] -n Squeezebox -c "C:\ProgramData\Squeezebox\Cache\spotty\70a51b 7b" --single-track $URL$ --disable-discovery --disable-audio-cache $START$ | [flac] -cs --channels=2 --sample-rate=44100 --bps=16 --endian=little --sign=signed --fast --totally-silent --ignore-chunk-sizes -
[23-02-07 14:45:26.7965] Plugins::Spotty::Plugin::updateTranscodingTable (270) [spotty] -n Squeezebox -c "C:\ProgramData\Squeezebox\Cache\spotty\70a51b 7b" --single-track $FILE$ --disable-discovery --disable-audio-cache $START$ | [sox] -q -t raw -b 16 -e signed -c 2 -r 44.1k -L - -t wav - | [SqueezeDSP] --id="d0:50:99:85:19:ea" --wav=true --wavo=true --d=24 | [flac] -cs -0 --totally-silent --ignore-chunk-sizes -
[23-02-07 14:45:26.7966] Plugins::Spotty::Plugin::updateTranscodingTable (270) [spotty-ogg] -n Squeezebox -c "C:\ProgramData\Squeezebox\Cache\spotty\70a51b 7b" --single-track $URL$ --disable-discovery --disable-audio-cache --pass-through $START$
[23-02-07 14:45:26.7966] Plugins::Spotty::Plugin::updateTranscodingTable (270) [spotty] -n Squeezebox -c "C:\ProgramData\Squeezebox\Cache\spotty\70a51b 7b" --single-track $URL$ --disable-discovery --disable-audio-cache $START$
[23-02-07 14:45:26.7967] Plugins::Spotty::Plugin::updateTranscodingTable (270) [spotty] -n Squeezebox -c "C:\ProgramData\Squeezebox\Cache\spotty\70a51b 7b" --single-track $URL$ --disable-discovery --disable-audio-cache $START$ | [lame] -r --silent -q $QUALITY$ $BITRATE$ - -
[23-02-07 14:45:26.7968] Plugins::Spotty::Plugin::updateTranscodingTable (270) [spotty] -n Squeezebox -c "C:\ProgramData\Squeezebox\Cache\spotty\70a51b 7b" --single-track $FILE$ --disable-discovery --disable-audio-cache $START$ | [sox] -q -t raw -b 16 -e signed -c 2 -r 44.1k -L - -t wav - | [SqueezeDSP] --id="a0:50:99:85:19:a1" --wav=true --wavo=true --d=24 | [flac] -cs -0 --totally-silent --ignore-chunk-sizes -
[23-02-07 14:45:26.8541] Slim::Utils::PluginDownloader::checkForUpdates (290) generating apps query to find latest plugin state
[23-02-07 14:45:26.8590] main::init (606) Server Jive init...
[23-02-07 14:45:26.8842] main::init (615) Server checkDataSource...
[23-02-07 14:45:26.8845] main::init (625) Library Browser init...
[23-02-07 14:45:26.8853] main::init (629) Server persist playlists...
[23-02-07 14:45:26.8854] main::init (665) Server HTTP enable...
[23-02-07 14:45:28.9162] main::init (673) Server done init...
[

[mherger]

The helper path is this
E:\GitHub\slimserver-win64\Bin\MSWin32-x64-multi-thread, E:\GitHub\slimserver-win64\Bin, C:\work\StrawberryPerl\perl\bin, C:\ProgramData\Squeezebox\Cache\InstalledPlugins\P lugins\C3PO\Bin, C:\ProgramData\Squeezebox\Cache\InstalledPlugins\P lugins\Spotty\Bin, C:\ProgramData\Squeezebox\Cache\InstalledPlugins\P lugins\SqueezeDSP\Bin, C:\ProgramData\Squeezebox\Cache\InstalledPlugins\P lugins\UPnPBridge\Bin

Ah, ok. That's very much non-standard. You're running LMS from the source? Using Strawberry Perl? LMS (and my plugins) make a lot of assumptions when it comes to Windows, as in 99.99% of all cases it's run from the Binary, and in some rare cases from ActivePerl. But Strawberry Perl? I only know about two persons in the universe doing this . In this case you probably have to live with the limitation you're seeing. I'm not going to look into this before there's at least one hand full of users of that setup .

BTW: even if you want to develop your own plugin you shouldn't need to have to run this non-standard. You should be able to run any plugin code from the Plugins folder.

[foxesden]

Yeah that's fine. I am using the Strawberry Perl version because it starts and stops instantly, whereas the normal instance takes a while. I was using the normal version, but with the number of tests I have been running it was taking too long.

[mherger]

Yeah that's fine. I am using the Strawberry Perl version because it starts and stops instantly, whereas the normal instance takes a while. I was using the normal version, but with the number of tests I have been running it was taking too long.

Did you compile additional binaries yourself? I know that ralphy had been working on a Strawberry port. Thus I'm a little surprised you were running it that way already. Would still be interesting to see what you get with os.paths logging enabled. That could give me a hint about what assumption is wrong for Strawberry. But maybe Ralphy has already addressed this?

Oh, just looked at your log again: MSWin32-x64-multi-thread - that's 64 bit, unlike the official build which is 32 bits.

[gorman]

Is there a reason why the native Ogg decoding is disabled and greyed out in settings (ie. not changeable)?

[mherger]

Is there a reason why the native Ogg decoding is disabled and greyed out in settings (ie. not changeable)?

Are you using volume normalization? In that case Ogg would be disabled.

[gorman]

Are you using volume normalization? In that case Ogg would be disabled.

I use Replaygain on my players, yes. Thanks for solving this. It makes sense. :-)

[mherger]

Velo17 what version of the Spotty helper are you using (see Settings/Advanced/Spotty)? Is there any hint about what it didn't like about Spotify's response?

Feel free to send me the server.log.zip: https://www.dropbox.com/request/T3RctyzGgNg0oFDubq6a

[Velo17]

[QUOTE=mherger;n1632854]Velo17 what version of the Spotty helper are you using (see Settings/Advanced/Spotty)? Is there any hint about what it didn't like about Spotify's response?

...that is shown as "spotty-hf (v1.3.0)" So far I can't tell what is causing the issue - but I enabled the spotty plugin log now and will upload you the server.log once I caught a new issue here!

[mherger]

Are you using Connect mode?

[Velo17]

Are you using Connect mode?

Yes with 3 players and until now I also enabled the connection testing to the Spotify servers (I use the german locale so I dont know the english original naming) - the other extended options are unselected and I now unselected the connection testing as well (to check if this maybe has to do with my problems)