Failed to get access token (401 Unauthorized)

michaelherger / Spotty-Plugin

A Spotify plugin for the Lyrion Music Server (fka. Logitech Media Server) and Squeezebox compatible players

116 stars 20 forks source link

Failed to get access token (401 Unauthorized) #108

Open chacq opened 9 months ago

chacq commented 9 months ago

Can't get Spotty to work on LMS, using a family premium account. Worked before of course, although I am having issues for a longer time now. At some point it worked with one player but not the other. piCorePlayer version was 5.0.1 until I updated everything gradually to 8.2.0 in the recent days.

I have serious problems getting Spotty to run at all on LMS and Rpi picoreplayer clients. I've seen the other "can't get access token" issues, but none seemed related and none had 401 Unauthorized error.

I have no idea, what else to try or how my setup could be special causing those errors. Thanks in advanc for any help :).

Software versions

Spotty (v4.9.1) LMS (8.3.2) PiCorePlayer (8.2.0)

Error form the logs

Error from server.log:

Plugins::Spotty::API::Web::__ANON__(251) API call: https://api.spotify.com/v1/views/desktop-home?content_limit=20&country=US&limit=20&locale=en_USxtamp=2023-12-16T18%3A40%3A00&types=album%2Cplaylist%2Cartist%2Cshow%2Cstation
Plugins::Spotty::API::Web::__ANON__(255) error: 401 Unauthorized
Plugins::Spotty::API::Token::gotTokenInfo (187) Failed to get access token.

From the API Call (which is also logged) I can see country=US and local=en_US. I am in Germany, can this be related?

What I did try:

[x] Tried a lot of Updates for related libs, packages...
[x] Remove account, add again, using different authentication methods (password vs. desktop app)
[x] update all piCorePlayers to version 8.2.0, installed LMS and plugins freshly (clean server, clean player)
[x] Created an app to get Client ID from spotify API
[x] Deactivate "import" of spotify account
[x] Deactivated pihole (no blocking for the spotify API seems to be active, ping of ap.spotify.com rsponds)
[x] Add account via Spotify Desktop App (as described)
[x] Changed branch to Stable and manually update

michaelherger commented 9 months ago

Please enable debug logging for plugin.spotty (Settings/Advanced/Logging), then remove the account again, and add it back in. Then upload the resulting server.log.zip to my inbox (https://www.dropbox.com/request/T3RctyzGgNg0oFDubq6a).

Would you have a firewall in place which might be blocking outgoing traffic?

chacq commented 9 months ago

Thanks for the quick reply and support! I did so and uploaded the server.log.zip.

The first error that appears there is:

Plugins::Spotty::AccountHelper::renameCacheFolder (136) Error: No newId found in '__AUTHENTICATE__'

The account creation via Spotify Desktop App failed two times, after restarting the app (also did an update before that) it work right away. (also did not work immediately before...) The rest is still the same.

I think there is no blocking of outgoing traffic that was not there before. The only new thing, is I am using pihole (a DNS server to block ads and stuff), which could interfere. I turned it off, which did not help.

Only thing: Maybe it has to be turned off while creating the account or something? However, it does not look like pihole did block any of the requests from my pcpServer...

Edit: So the "unauthorized" issue is not the main issue, this just happens because it failed to get a token and then makes a request without it. The request opened in a browser is answered with 401 "no token provided"

https://api.spotify.com/v1/views/desktop-home?content_limit=20&country=US&limit=20&locale=en_US%C3%97tamp=2023-12-16T17%3A30%3A00&types=album%2Cplaylist%2Cartist%2Cshow%2Cstation

Thanks again :)

michaelherger commented 9 months ago

In that log file you'll find the full command spotty uses to get a token. Could you please run the same from a shell without the --save-token parameter, but with -v(verbose) added?

chacq commented 9 months ago

If I ssh into the server and run the same spotty-hf command in verbose (also removing some double quotes), simply nothing happens.

running > spotty-hf with no arguments results in the same effect, however running it with -h flag works as expected.

Looking at top the command also doesn't seem very active. What I don't understand is, where the "couldn't get token" message comes from. Is it generated, because this command timed out?

michaelherger commented 9 months ago

Oh, I'm sorry... You'll also have to add the --get-token parameter (replacing --save-token /path/to/file). That way the token should be printed to the console. Don't post the full token here.

chacq commented 9 months ago

Ok, this works, but I am getting {"error":"Failed to get access token."} instead of a token, and no further info, although I'm using the --verbose flag.

michaelherger commented 9 months ago

Hmm... that's odd. Did you add all your Spotify accounts to the client ID configuration? If you have more than one, or create the client with a different account than the one you're using in Spotty you'll have to add them in the Spotify dev portal.

chacq commented 9 months ago

I tried it with and without the client ID (-i flag), same result. I never needed the client ID, so this should not be the issue, I think. (I'm a bit confused about this. Using the client ID is optional, right?

Can I somehow get a "more verbose" reason on why/how getting the Token failed? Should I try to establish a connection to my spotify account on my linux desktop manually to verify my credentials work etc? How would I got about this?

I did just create the app in order to get a client ID. Now I also added my account by email, still the same result.

michaelherger commented 9 months ago

I'm running out of ideas... Is the server running on a pCP, too? The system's time is correct? Could you try to run LMS & Spotty on a different computer, even a different network? Just to see whether it's a problem with your account, and not your environment?

And make sure you've paid your subscription 😄 - Premium is a requirement.

chacq commented 9 months ago

Ok, so I did some more tests.

Server runs pCP, too, system time looks good, premium (family) is there, also it all worked before.

I tried my player and server in another network which also has a LMS server and clients. The player worked well with the other server (as expected) but the server failed there in the same way. I will try running LMS on another RPi.

I removed the account from the family plan and added it again, still the same.

Only new thing I found in the logs when adding the account to spotty was:

[24-01-01 17:00:01.3194] Plugins::Spotty::AccountHelper::renameCacheFolder (134) Trying to rename __AUTHENTICATE__ to 
[24-01-01 17:00:01.3197] Plugins::Spotty::AccountHelper::renameCacheFolder (136) Error: No newId found in '__AUTHENTICATE__'
[24-01-01 17:00:01.3202] Plugins::Spotty::AccountHelper::renameCacheFolder (136) Backtrace:

   frame 0: Slim::Utils::Log::logBacktrace (/usr/local/slimserver/Cache/InstalledPlugins/Plugins/Spotty/AccountHelper.pm line 136)
   frame 1: Plugins::Spotty::AccountHelper::renameCacheFolder (/usr/local/slimserver/Cache/InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 187)
   frame 2: Plugins::Spotty::Settings::Auth::cleanup (/usr/local/slimserver/Cache/InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 197)
   frame 3: Plugins::Spotty::Settings::Auth::shutdownHelper (/usr/local/slimserver/Cache/InstalledPlugins/Plugins/Spotty/Settings.pm line 104)
   frame 4: Plugins::Spotty::Settings::handler (/usr/local/slimserver/Slim/Web/HTTP.pm line 1168)
   frame 5: Slim::Web::HTTP::generateHTTPResponse (/usr/local/slimserver/Slim/Web/HTTP.pm line 933)
   frame 6: Slim::Web::HTTP::processURL (/usr/local/slimserver/Slim/Web/HTTP.pm line 728)
   frame 7: Slim::Web::HTTP::processHTTP (/usr/local/slimserver/Slim/Networking/IO/Select.pm line 122)
   frame 8: (eval) (/usr/local/slimserver/Slim/Networking/IO/Select.pm line 118)
   frame 9: Slim::Networking::IO::Select::__ANON__ (/usr/local/slimserver/Slim/Networking/IO/Select.pm line 167)
   frame 10: (eval) (/usr/local/slimserver/Slim/Networking/IO/Select.pm line 167)
   frame 11: Slim::Networking::IO::Select::loop (/usr/local/slimserver/slimserver.pl line 721)
   frame 12: main::idle (/usr/local/slimserver/slimserver.pl line 671)
   frame 13: main::main (/usr/local/slimserver/slimserver.pl line 1210)

[24-01-01 17:00:01.3224] Plugins::Spotty::API::Token::get (226) Didn't find cached token. Need to refresh.

chacq commented 8 months ago

So, I've put the SD-Card of the server in another Rpi (Rpi 4b instead of 3b+), with the same result.
Then I put a completely fresh pcp8.2.0 on a new sd-card into the 3b+, same result.
I removed the account and used email+password manually to add the account and this time it worked.

So what I noticed earlier was that using the Spotify-Desktop App to add the account was not completing:

The account was listed in the Spotty-Plugin settings page, but the Desktop App was still "processing" without finishing. I think the new authentication process should include a check of getting a Token and should fail, instead of adding a broken account with no warning.

Thanks for your support ;)

rsplaul commented 8 months ago

I can confirm that the authorization via Spotify Desktop app is buggy. I had repeated issues with the very same error Plugins::Spotty::API::Token::_gotTokenInfo (187) Failed to get access token. (sometimes in combination with an error stating that the credentials file could not be read or was empty) and tried everything from restarting LMS to removing and re-adding the Spotify account(s) but nothing helped. Manually adding the Spotify credentials of both family accounts in the settings indeed did the trick!

geni1105 commented 7 months ago

After many years with Spotty, I now have the same issue, no matter what kind of authorization - via Spotify Desktop app, by user name, or by email address :-( Strangely, I can still play Spotify music from my library, just the Spotty menu is empty except for the "Failed to get access token" message.

This is on a Mac mini with High Sierra (10.13), LMS 8.4.0 and Spotty 4.9.2.

Log from start of LMS: [24-02-18 18:16:36.7852] main::init (380) Starting Logitech Media Server (v8.4.0, 1696247852, Mon Oct 2 14:21:23 CEST 2023) perl 5.018002 - darwin-thread-multi-2level [24-02-18 18:16:42.7259] Plugins::Spotty::API::ANON (1454) API call: me [24-02-18 18:16:42.7263] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 18:16:42.7291] Plugins::Spotty::API::ANON (1454) API call: me/player/devices [24-02-18 18:16:42.7293] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 18:16:43.0299] Plugins::Spotty::API::ANON (1454) API call: me [24-02-18 18:16:43.0301] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 18:16:43.0320] Plugins::Spotty::API::ANON (1454) API call: tracks?ids=07wfYc6rDVk68UkgdFSwPg%2C0VCMEt3FKVLEFHS6hqLTL0%2C0WqRaXDHj4oO039PweeqB7%2C0ZmTk8Ow3XUCjSvRqC1TNV%2C1CrH22ThmHF3YNMee3Hc9p%2C1mBrH4Dqc3FWAEgogUb015%2C20Cd8RxYvcrQiw0JvvFpWJ%2C21iLVgHR5ZPfRIezfLRtvC%2C2qjsuGNb7QEXvjaonKi5YS%2C2x0NM56MkBoiK3JuVYbsmt%2C3lslWxZtPlH5TKJQnW4oJx%2C5JtSlAE2JGktcZLhxY98xc%2C5axjp8Cnceaf1yzHW6nopf%2C6eIoWM00zDCpoer2ZHYaAw%2C6gfDP6HI76Q8XICeqXzNvi%2C6gp88V32qZHUIbKcVk8PUw%2C6trGef3X7MEeDbhPa2Sxxe%2C759aSBjo9N6PXyXVpDIfj7&market=from_token [24-02-18 18:16:43.0322] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 18:16:43.0341] Plugins::Spotty::API::ANON (1454) API call: tracks?ids=07wfYc6rDVk68UkgdFSwPg%2C0VCMEt3FKVLEFHS6hqLTL0%2C0WqRaXDHj4oO039PweeqB7%2C0ZmTk8Ow3XUCjSvRqC1TNV%2C1CrH22ThmHF3YNMee3Hc9p%2C1mBrH4Dqc3FWAEgogUb015%2C20Cd8RxYvcrQiw0JvvFpWJ%2C21iLVgHR5ZPfRIezfLRtvC%2C2qjsuGNb7QEXvjaonKi5YS%2C2x0NM56MkBoiK3JuVYbsmt%2C3lslWxZtPlH5TKJQnW4oJx%2C5JtSlAE2JGktcZLhxY98xc%2C5axjp8Cnceaf1yzHW6nopf%2C6eIoWM00zDCpoer2ZHYaAw%2C6gfDP6HI76Q8XICeqXzNvi%2C6gp88V32qZHUIbKcVk8PUw%2C6trGef3X7MEeDbhPa2Sxxe%2C759aSBjo9N6PXyXVpDIfj7&market=from_token [24-02-18 18:16:43.0343] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 18:16:44.6294] Plugins::Spotty::API::ANON (1454) API call: tracks?ids=07wfYc6rDVk68UkgdFSwPg%2C0VCMEt3FKVLEFHS6hqLTL0%2C0WqRaXDHj4oO039PweeqB7%2C0ZmTk8Ow3XUCjSvRqC1TNV%2C1CrH22ThmHF3YNMee3Hc9p%2C1mBrH4Dqc3FWAEgogUb015%2C20Cd8RxYvcrQiw0JvvFpWJ%2C21iLVgHR5ZPfRIezfLRtvC%2C2qjsuGNb7QEXvjaonKi5YS%2C2x0NM56MkBoiK3JuVYbsmt%2C3lslWxZtPlH5TKJQnW4oJx%2C5JtSlAE2JGktcZLhxY98xc%2C5axjp8Cnceaf1yzHW6nopf%2C6eIoWM00zDCpoer2ZHYaAw%2C6gfDP6HI76Q8XICeqXzNvi%2C6gp88V32qZHUIbKcVk8PUw%2C6trGef3X7MEeDbhPa2Sxxe%2C759aSBjo9N6PXyXVpDIfj7&market=from_token [24-02-18 18:16:44.6297] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 18:16:44.6316] Plugins::Spotty::API::ANON (1454) API call: tracks?ids=07wfYc6rDVk68UkgdFSwPg%2C0VCMEt3FKVLEFHS6hqLTL0%2C0WqRaXDHj4oO039PweeqB7%2C0ZmTk8Ow3XUCjSvRqC1TNV%2C1CrH22ThmHF3YNMee3Hc9p%2C1mBrH4Dqc3FWAEgogUb015%2C20Cd8RxYvcrQiw0JvvFpWJ%2C21iLVgHR5ZPfRIezfLRtvC%2C2qjsuGNb7QEXvjaonKi5YS%2C2x0NM56MkBoiK3JuVYbsmt%2C3lslWxZtPlH5TKJQnW4oJx%2C5JtSlAE2JGktcZLhxY98xc%2C5axjp8Cnceaf1yzHW6nopf%2C6eIoWM00zDCpoer2ZHYaAw%2C6gfDP6HI76Q8XICeqXzNvi%2C6gp88V32qZHUIbKcVk8PUw%2C6trGef3X7MEeDbhPa2Sxxe%2C759aSBjo9N6PXyXVpDIfj7&market=from_token [24-02-18 18:16:44.6318] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 18:16:44.6708] Plugins::Spotty::API::ANON (1454) API call: tracks?ids=20Cd8RxYvcrQiw0JvvFpWJ&market=from_token [24-02-18 18:16:44.6711] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 18:16:44.7078] Plugins::Spotty::API::ANON (1454) API call: tracks?ids=3lslWxZtPlH5TKJQnW4oJx&market=from_token

geni1105 commented 7 months ago

Update with more detailed logs - seems like the authentication is ok, but there are communication timeouts? Thanks for any hints!

[24-02-18 20:03:10.6613] Plugins::Spotty::Settings::Auth::startHelper (163) Starting Spotty Connect deamon: /Users/ge_ni/Library/Caches/Squeezebox/InstalledPlugins/Plugins/Spotty/Bin/darwin-thread-multi-2level/spotty -c /Users/ge_ni/Library/Caches/Squeezebox/spotty/AUTHENTICATE -n Spotify Anmeldung (Georg's Mac mini) -a --ap-port=12321 [24-02-18 20:03:10.7232] Plugins::Spotty::AccountHelper::renameCacheFolder (134) Trying to rename AUTHENTICATE to b2d9b707 [24-02-18 20:03:10.7245] Plugins::Spotty::Settings::Auth::shutdownHelper (193) Quitting authentication daemon [24-02-18 20:03:10.7257] Plugins::Spotty::AccountHelper::renameCacheFolder (134) Trying to rename AUTHENTICATE to [24-02-18 20:03:10.7276] Plugins::Spotty::API::Web::home (45) Returning cached Home menu structure for ge_ni (1231234123412341234) [24-02-18 20:03:10.7320] Plugins::Spotty::Helper::_findBin (192) Trying helper application: /Users/ge_ni/Library/Caches/Squeezebox/InstalledPlugins/Plugins/Spotty/Bin/darwin-thread-multi-2level/spotty [24-02-18 20:03:10.7621] Plugins::Spotty::Helper::_findBin (195) Found helper application: /Users/ge_ni/Library/Caches/Squeezebox/InstalledPlugins/Plugins/Spotty/Bin/darwin-thread-multi-2level/spotty [24-02-18 20:03:21.0175] Plugins::Spotty::Importer::needsUpdate (328) Checking Spotify library state... [24-02-18 20:03:21.0187] Plugins::Spotty::API::ANON (1352) Trying to read from cache for me [24-02-18 20:03:21.0189] Plugins::Spotty::API::ANON (1361) API call: me [24-02-18 20:03:21.0218] Plugins::Spotty::Importer::ANON (349) Got playlist snapshot IDs: { "1KHa1sTySV9PZY47RNWvNH" => "MTQ2LGQzNTVmMGZhYjZkZGVhNzEwMzY5ZjM5ZTY1MjNmY2QzZTJiMDM3Mjc=", "37i9dQZEVXcUtuPpMovwxf" => "1708368947", "37i9dQZF1DWT9XEOPDgFX3" => "1708368947", "37i9dQZF1DX2Nc3B70tvx0" => "1708368947", "37i9dQZF1DXdd3gw5QVjt9" => "1708368947", "37i9dQZF1DZ06evO18SggM" => "1708368947", "38n1b62iip3o8PqBUrps0G" => "MTksMjYwNTFiY2E0OGY2ZWQ1NTMyOGUyYTBkOWY2N2IwZjA2MjViNjBmZg==", "3JFmt7BOm7ih2DtXPREV2V" => "NjIsMzQ3YzZlMGNhNWVkMjYwMTViZjkxN2M0MjhiMzE0NDMxODgzNWU1ZQ==", "4enwjxQCGbI9B5nACvXrHb" => "MTQxLGFhMjUyZGJmMDY3M2IyZjQ2YmRmMDQ4ZWVhOGU3ZGE5Yzc1MzAyMTk=", "5hu47aGARjQnDfEeVlFm4m" => "MTk0LGIzMjI3NDhhNTZiMGIxZTVmNGRlNmZjNmE0ZjJiNjE3MWU2NmJkZDk=", "5i3M4FaZdzf9cgn5otpfKS" => "ODgsMTg0YjZmZGM5ZjI2YzkyMWFmZTYwYWZmNTEwZjdjODZhNWU0ZmFkNg==", "6I7u227jJ7IKCbHMCcFelE" => "MTQsMTRhOTExN2UxOWE1MGU4MzkxZmY0NGYwMzY4NGE0YzM4MjY4ZTgwYw==", "6sgB92tu25p3sKi0wnsfPT" => "MjYsNjBjOWI5NzE2Yzk1NWVlNDc4MDc5MTFjNjgwZjI5Y2FlNzAyNjg5OA==", } [24-02-18 20:03:21.0226] Plugins::Spotty::API::ANON (1352) Trying to read from cache for users/ge_ni/playlists?limit=50 [24-02-18 20:03:21.0231] Plugins::Spotty::API::ANON (1361) API call: users/ge_ni/playlists?limit=50 [24-02-18 20:03:21.1635] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 20:03:21.1640] Plugins::Spotty::API::ANON (1469) undef [24-02-18 20:03:21.1723] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 20:03:21.1726] Plugins::Spotty::API::ANON (1469) undef [24-02-18 20:03:21.1738] Plugins::Spotty::API::ANON (1352) Trying to read from cache for me/albums?limit=1 [24-02-18 20:03:21.1740] Plugins::Spotty::API::ANON (1361) API call: me/albums?limit=1 [24-02-18 20:03:21.2549] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-18 20:03:21.2551] Plugins::Spotty::API::ANON (1469) undef [24-02-18 20:03:21.2554] Plugins::Spotty::Importer::ANON (390) Latest album update: { lastUpdate => "144|2020-01-04T13:22:24Z|", latestUpdate => "||" } [24-02-18 20:03:23.8532] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons... [24-02-18 20:03:23.8536] Plugins::Spotty::Connect::DaemonManager::initHelpers (122) This is the sync group's master, or a standalone player with Spotify Connect enabled: b8:27:eb:d7:6a:7f [24-02-18 20:03:32.4197] Plugins::Spotty::ProtocolHandler::getMetadataFor (190) Returning metadata cached in song object for spotify:track:65ij88ASYO5zfA6VfesajY [24-02-18 20:03:32.4206] Plugins::Spotty::ProtocolHandler::getMetadataFor (190) Returning metadata cached in song object for spotify:track:65ij88ASYO5zfA6VfesajY [24-02-18 20:03:51.0826] Plugins::Spotty::API::ANON (1458) error: Connect timed out: Bad file descriptor [24-02-18 20:03:51.0833] Plugins::Spotty::API::ANON (1469) undef [24-02-18 20:03:51.1256] Plugins::Spotty::API::ANON (1458) error: Connect timed out: Bad file descriptor [24-02-18 20:03:51.1259] Plugins::Spotty::API::ANON (1469) undef [24-02-18 20:03:51.2190] Plugins::Spotty::API::ANON (1458) error: Connect timed out: Bad file descriptor [24-02-18 20:03:51.2195] Plugins::Spotty::API::ANON (1469) undef

michaelherger commented 7 months ago

@geni1105 can you check what IO::Socket::SSL you're using (Settings/Information)? If your installation is using the OS' Perl, then that might be outdated, causing web requests to fail.

geni1105 commented 7 months ago

Thanks for the quick reaction!

Strangely, settings/information is completely empty regarding perl and module versions (see below). "perl -v" gives 5.18, this is the OS's perl under /usr/bin. When I start from the command line with this perl version, the communication errors occur. Starting from the prefpane's perl (/Library/PreferencePanes/Squeezebox.prefPane/Contents/perl/bin/perl) does not work at all, it aborts with an error: dyld: lazy symbol binding failed: Symbol not found: ____chkstk_darwin Referenced from: /Library/PreferencePanes/Squeezebox.prefPane/Contents/server/CPAN/arch/5.34/darwin-thread-multi-2level/auto/Net/SSLeay/SSLeay.bundle Expected in: /usr/lib/libSystem.B.dylib

Edit: there's an openssl under /usr/bin which reports LibreSSL 2.2.7

Logitech Media Server-Status Logitech Media Server Version: 8.4.0 - 1701875738 @ Thu Feb 8 12:45:31 CET 2024 Hostname: Georgs-Mac-mini.local IP-Adresse des Servers: 192.168.68.101 Server-HTTP-Portnummer: 9000 Betriebssystem: macOS 10.13.6 - DE - utf8 Plattformarchitektur: x86_64 Datenbankversion: SQLite Anzahl erkannter Player: 0

Perl- und Modulversionen

Musiksammlungsstatistik Anzahl Titel: 9.677 Anzahl Alben: 791 Anzahl Interpreten: 2.074 ...

michaelherger commented 7 months ago

I think this is more of a LMS on Mac issue than Spotty... Could you please check your server.log file from Settings/Information, after you have accessed that page? There should be at least some failure information for the module reporting.

And then please tell me what the following line would return:

perl -MIO::Socket::SSL -e 'print $IO::Socket::SSL::VERSION'

geni1105 commented 7 months ago

Installed the LMS 8.3.0 now, and this one gives version information: Perl-Version: 5.18.2 - darwin-thread-multi-2level Audio::Scan: 1.05 IO::Socket::SSL: 2.056 Datenbankversion: DBD::SQLite 1.58 (sqlite 3.22.0)

The behavior regarding Spotty is the same, though.

perl -MIO::Socket::SSL -e 'print $IO::Socket::SSL::VERSION' returns 2.056

Reinstalled 8.4.0, and now it also gives the version information above. Hmm. But the error is still in the logs - here's a LMS stop and restart sequence:

[24-02-19 11:17:26.3664] Plugins::Spotty::Importer::ANON (390) Latest album update: { lastUpdate => "144|2020-01-04T13:22:24Z|", latestUpdate => "||" } [24-02-19 11:17:38.0010] Plugins::Spotty::AccountHelper::purgeAudioCache (236) Starting temporary file cleanup... (/tmp - uid: 501) [24-02-19 11:17:38.0012] Plugins::Spotty::AccountHelper::purgeAudioCache (257) Audio cache cleanup done! [24-02-19 11:17:38.0015] Plugins::Spotty::AccountHelper::renameCacheFolder (134) Trying to rename AUTHENTICATE to [24-02-19 11:17:38.0019] Plugins::Spotty::Connect::DaemonManager::stopHelper (176) Shutting down Connect daemon for b8:27:eb:d7:6a:7f (pid: 34958) [24-02-19 11:17:38.0021] Plugins::Spotty::Connect::Daemon::stop (144) Quitting Spotty Connect daemon for b8:27:eb:d7:6a:7f [24-02-19 11:17:45.2705] main::init (380) Starting Logitech Media Server (v8.4.0, 1696247852, Mon Oct 2 14:21:23 CEST 2023) perl 5.018002 - darwin-thread-multi-2level [24-02-19 11:17:46.7076] main::init (380) Starting Logitech Media Server (v8.4.0, 1696247852, Mon Oct 2 14:21:23 CEST 2023) perl 5.018002 - darwin-thread-multi-2level [24-02-19 11:17:51.4883] Plugins::Spotty::API::ANON (1454) API call: me [24-02-19 11:17:51.4886] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-19 11:17:51.4909] Plugins::Spotty::API::ANON (1454) API call: me/player/devices [24-02-19 11:17:51.4911] Plugins::Spotty::API::ANON (1458) error: Connect timed out: [24-02-19 11:18:21.4016] Plugins::Spotty::API::ANON (1454) API call: me [24-02-19 11:18:21.4021] Plugins::Spotty::API::ANON (1458) error: Connect timed out: Bad file descriptor [24-02-19 11:18:21.4414] Plugins::Spotty::API::ANON (1454) API call: me/player/devices [24-02-19 11:18:21.4418] Plugins::Spotty::API::ANON (1458) error: Connect timed out: Bad file descriptor

geni1105 commented 7 months ago

Update: I followed the instructions from https://forums.slimdevices.com/forum/user-forums/logitech-media-server/106382-error-can-t-connect-to-remote-server-to-retrieve?p=1504747#post1504747 and OpenSSL is now updated to 2.085.

Everything seems to work again - thanks a lot :-))

NikolajChristensen commented 6 months ago

I can confirm that I had to manually add the Spotify account in LMS for it to work. Got the "failed to get access token" if I authorized via the discovery stuff in the official spotify app.

joshcomley commented 5 months ago

Hello!

I am completely unable to get a token anymore, also. I have read all the above, tried username/email and password login, tried desktop connect auth, phone connect auth.

Below is the relevant bit from my logs (from when I delete and re-add my user via username/password auth).

I am using the fallback access point.

I am not sure how to check my OpenSSL version, but I don't seem to be having any timeouts.

Edit: I have also tried with and without a client ID.

[24-04-05 03:33:11.8663] Plugins::Spotty::Settings::Auth::startHelper (163) Starting Spotty Connect deamon: 
/config/lms/cache/InstalledPlugins/Plugins/Spotty/Bin/aarch64-linux/spotty -c /config/lms/cache/spotty/__AUTHENTICATE__ -n Spotify Authorization (homeassistant - LMS HA Addon) -a --ap-port=12321
[24-04-05 03:33:11.8764] Plugins::Spotty::Helper::_findBin (192) Trying helper application: /config/lms/cache/InstalledPlugins/Plugins/Spotty/Bin/aarch64-linux/spotty
[24-04-05 03:33:11.8930] Plugins::Spotty::Helper::_findBin (195) Found helper application: /config/lms/cache/InstalledPlugins/Plugins/Spotty/Bin/aarch64-linux/spotty
[24-04-05 03:33:11.8934] Plugins::Spotty::Helper::_findBin (192) Trying helper application: /config/lms/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf
[24-04-05 03:33:47.9581] Plugins::Spotty::Settings::Auth::handler (69) Trying to authenticate using: "/config/lms/cache/InstalledPlugins/Plugins/Spotty/Bin/aarch64-linux/spotty" -c "/config/lms/cache/spotty/__AUTHENTICATE__" -n "Spotify Authorization (homeassistant - LMS HA Addon)" -u "joshcomley" -p "********" -a --disable-discovery --ap-port 12321 --verbose
[24-04-05 03:33:48.2205] Plugins::Spotty::Settings::Auth::handler (74) Got response: authorized
[24-04-05 03:33:48.2209] Plugins::Spotty::Settings::Auth::shutdownHelper (193) Quitting authentication daemon
[24-04-05 03:33:48.2219] Plugins::Spotty::AccountHelper::renameCacheFolder (134) Trying to rename __AUTHENTICATE__ to 96ad2177
[24-04-05 03:33:48.2224] Plugins::Spotty::AccountHelper::renameCacheFolder (134) Trying to rename __AUTHENTICATE__ to 
[24-04-05 03:33:48.2226] Plugins::Spotty::AccountHelper::renameCacheFolder (136) Error: No newId found in '__AUTHENTICATE__'
[24-04-05 03:33:48.2228] Plugins::Spotty::AccountHelper::renameCacheFolder (136) Backtrace:

   frame 0: Slim::Utils::Log::logBacktrace (/config/lms/cache/InstalledPlugins/Plugins/Spotty/AccountHelper.pm line 136)
   frame 1: Plugins::Spotty::AccountHelper::renameCacheFolder (/config/lms/cache/InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 187)
   frame 2: Plugins::Spotty::Settings::Auth::cleanup (/config/lms/cache/InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 91)
   frame 3: Plugins::Spotty::Settings::Auth::handler (/usr/share/perl5/Slim/Web/HTTP.pm line 1168)
   frame 4: Slim::Web::HTTP::generateHTTPResponse (/usr/share/perl5/Slim/Web/HTTP.pm line 933)
   frame 5: Slim::Web::HTTP::processURL (/usr/share/perl5/Slim/Web/HTTP.pm line 728)
   frame 6: Slim::Web::HTTP::processHTTP (/usr/share/perl5/Slim/Networking/IO/Select.pm line 122)
   frame 7: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 118)
   frame 8: Slim::Networking::IO::Select::__ANON__ (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167)
   frame 9: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167)
   frame 10: Slim::Networking::IO::Select::loop (/usr/sbin/squeezeboxserver line 732)
   frame 11: main::idle (/usr/sbin/squeezeboxserver line 681)
   frame 12: main::main (/usr/sbin/squeezeboxserver line 1223)

[24-04-05 03:33:48.2551] Plugins::Spotty::AccountHelper::renameCacheFolder (134) Trying to rename __AUTHENTICATE__ to 
[24-04-05 03:33:48.2553] Plugins::Spotty::AccountHelper::renameCacheFolder (136) Error: No newId found in '__AUTHENTICATE__'
[24-04-05 03:33:48.2555] Plugins::Spotty::AccountHelper::renameCacheFolder (136) Backtrace:

   frame 0: Slim::Utils::Log::logBacktrace (/config/lms/cache/InstalledPlugins/Plugins/Spotty/AccountHelper.pm line 136)
   frame 1: Plugins::Spotty::AccountHelper::renameCacheFolder (/config/lms/cache/InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 187)
   frame 2: Plugins::Spotty::Settings::Auth::cleanup (/config/lms/cache/InstalledPlugins/Plugins/Spotty/Settings.pm line 61)
   frame 3: Plugins::Spotty::Settings::handler (/usr/share/perl5/Slim/Web/HTTP.pm line 1168)
   frame 4: Slim::Web::HTTP::generateHTTPResponse (/usr/share/perl5/Slim/Web/HTTP.pm line 933)
   frame 5: Slim::Web::HTTP::processURL (/usr/share/perl5/Slim/Web/HTTP.pm line 728)
   frame 6: Slim::Web::HTTP::processHTTP (/usr/share/perl5/Slim/Networking/IO/Select.pm line 122)
   frame 7: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 118)
   frame 8: Slim::Networking::IO::Select::__ANON__ (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167)
   frame 9: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167)
   frame 10: Slim::Networking::IO::Select::loop (/usr/sbin/squeezeboxserver line 732)
   frame 11: main::idle (/usr/sbin/squeezeboxserver line 681)
   frame 12: main::main (/usr/sbin/squeezeboxserver line 1223)

[24-04-05 03:33:48.2560] Plugins::Spotty::AccountHelper::renameCacheFolder (134) Trying to rename __AUTHENTICATE__ to 
[24-04-05 03:33:48.2561] Plugins::Spotty::AccountHelper::renameCacheFolder (136) Error: No newId found in '__AUTHENTICATE__'
[24-04-05 03:33:48.2563] Plugins::Spotty::AccountHelper::renameCacheFolder (136) Backtrace:

   frame 0: Slim::Utils::Log::logBacktrace (/config/lms/cache/InstalledPlugins/Plugins/Spotty/AccountHelper.pm line 136)
   frame 1: Plugins::Spotty::AccountHelper::renameCacheFolder (/config/lms/cache/InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 187)
   frame 2: Plugins::Spotty::Settings::Auth::cleanup (/config/lms/cache/InstalledPlugins/Plugins/Spotty/Settings/Auth.pm line 197)
   frame 3: Plugins::Spotty::Settings::Auth::shutdownHelper (/config/lms/cache/InstalledPlugins/Plugins/Spotty/Settings.pm line 104)
   frame 4: Plugins::Spotty::Settings::handler (/usr/share/perl5/Slim/Web/HTTP.pm line 1168)
   frame 5: Slim::Web::HTTP::generateHTTPResponse (/usr/share/perl5/Slim/Web/HTTP.pm line 933)
   frame 6: Slim::Web::HTTP::processURL (/usr/share/perl5/Slim/Web/HTTP.pm line 728)
   frame 7: Slim::Web::HTTP::processHTTP (/usr/share/perl5/Slim/Networking/IO/Select.pm line 122)
   frame 8: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 118)
   frame 9: Slim::Networking::IO::Select::__ANON__ (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167)
   frame 10: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167)
   frame 11: Slim::Networking::IO::Select::loop (/usr/sbin/squeezeboxserver line 732)
   frame 12: main::idle (/usr/sbin/squeezeboxserver line 681)
   frame 13: main::main (/usr/sbin/squeezeboxserver line 1223)

joshcomley commented 5 months ago

Additional info: I tried using a different Spotify premium account and the same result. I am running the LMS add-on in HA, but there were some plugin updates earlier today - although I'm not sure which ones! I always just click them through without paying much attention :( it was working fine, then it all just stopped.

Edit: running on Pi 5

Edit 2:

Server info copy and paste:

Version: 8.4.0 - 1707213032 @ Thu 08 Feb 2024 12:22:32 PM CET
Hostname: fc57b866-lms
Server IP Address: 192.168.68.93
Operating system: Debian (Docker Home Assistant Addon) - EN - utf8
Platform Architecture: aarch64-linux
Perl Version: 5.36.0 - aarch64-linux-gnu-thread-multi
Audio::Scan: 1.09
IO::Socket::SSL: 2.081
Database Version: DBD::SQLite 1.58 (sqlite 3.22.0)

michaelherger commented 5 months ago

You only post a log snippet from the auth itself - which seems to succeed. But there's no sign of what you're doing to get the "failed to get access token". Actually: not even that message is part of your log. Did you configure your Client ID for Spotty?

And you should update your LMS to 8.5.

joshcomley commented 5 months ago

Thanks for the reply! I can't update to 8.5 because the version is tied to the HA add-on.

I do have the Spotify Client ID set. I can't find anywhere in the logs that it's trying to get the token.

With log level debug, the log was huge, but if I strip out the non-essential lines you get this as my log over several hours and reboots last night:

server (6) - 2.log

(you can ignore the last five or so lines because I had manually created the __AUTHENTICATE__ folder very briefly)

Is there a keyword I can search for for the token attempt? I suspect it's not even trying, hence it fails for multiple Spotify Premium accounts.

So you can see nothing unimportant got stripped out here is the code I used to strip it:

    var lines = File.ReadAllLines(@"C:\Users\joshc\Downloads\server (6).log").AsEnumerable();
    foreach (var key in new[] {
    "playlistEntryIsValid",
    "doesn't exist on disk - skipping!",
    "getBulkMetadata",
    "getMetadataFor",
    "spotify:track",
    "This is a standalone player with Spotify Connect disabled",
    })
    {
        lines = lines.Where(l => !l.Contains(key));
    }
    foreach (var key in

@"  album => 
  artist =>
  bitrate =>
  cover =>
  duration =>
  icon =>
  originaltype =>
  originalType =>
  title =>
  type =>
  url =>".Split('\n').Select(l => l.Replace(" ", @"\s+").Trim()))
    {
        lines = lines.Where(l => !Regex.IsMatch(l, $"^{key}"));
    }
    lines = lines.Where(l => !Regex.IsMatch(l.Trim(), @"^(\)|}|\])$"));

    File.WriteAllLines(@"C:\Users\joshc\Downloads\server (6) - 2.log", lines);

joshcomley commented 5 months ago

Here's everything from a reboot just now, looks like Can't use string ("1") as a symbol is part of it:

[24-04-05 09:13:02.2445] main::init (386) Starting Logitech Media Server (v8.4.0, 1707213032, Thu 08 Feb 2024 12:22:32 PM CET) perl 5.036000 - aarch64-linux-gnu-thread-multi
[24-04-05 09:13:02.7179] Plugins::CastBridge::Plugin::initPlugin (82) $VAR1 = {
          'binArch' => 'aarch64-linux',
          'isDebian' => 1,
          'osName' => 'Debian (Docker Home Assistant Addon)',
          'uid' => 'squeezeboxserver',
          'os' => 'Linux',
          'osArch' => 'aarch64-linux'
        };
[24-04-05 09:13:02.8338] Plugins::RaopBridge::Plugin::initPlugin (72) $VAR1 = {
          'binArch' => 'aarch64-linux',
          'isDebian' => 1,
          'osName' => 'Debian (Docker Home Assistant Addon)',
          'uid' => 'squeezeboxserver',
          'os' => 'Linux',
          'osArch' => 'aarch64-linux'
        };
[24-04-05 09:13:02.8405] Plugins::Spotty::AccountHelper::purgeAudioCache (236) Starting temporary file cleanup... (/config/lms/cache/spotty - uid: 1000)
[24-04-05 09:13:02.8407] Plugins::Spotty::AccountHelper::purgeAudioCache (257) Audio cache cleanup done!
[24-04-05 09:13:02.8408] Plugins::Spotty::AccountHelper::purgeAudioCache (236) Starting temporary file cleanup... (/tmp - uid: 1000)
[24-04-05 09:13:02.8408] Plugins::Spotty::AccountHelper::purgeAudioCache (257) Audio cache cleanup done!
[24-04-05 09:13:02.8822] Plugins::Spotty::OPML::init (117) Successfully registered BrowseArtist handler for Spotify
[24-04-05 09:13:02.8828] Plugins::Spotty::Helper::_findBin (192) Trying helper application: /config/lms/cache/InstalledPlugins/Plugins/Spotty/Bin/aarch64-linux/spotty
[24-04-05 09:13:02.9013] Plugins::Spotty::Helper::helperCheck (118) Found helper capabilities table: do {
  my $a = {
    "autoplay"             => bless(do{\(my $o = 1)}, "JSON::XS::Boolean"),
    "debug"                => bless(do{\(my $o = 0)}, "JSON::XS::Boolean"),
    "lms-auth"             => 'fix',
    "ogg-direct"           => 'fix',
    "podcasts"             => 'fix',
    "save-token"           => 'fix',
    "version"              => "1.3.0",
    "volume-normalisation" => 'fix',
    "zeroconf-port"        => 'fix',
  };
  $a->{"lms-auth"} = \${$a->{"autoplay"}};
  $a->{"ogg-direct"} = \${$a->{"autoplay"}};
  $a->{"podcasts"} = \${$a->{"autoplay"}};
  $a->{"save-token"} = \${$a->{"autoplay"}};
  $a->{"volume-normalisation"} = \${$a->{"autoplay"}};
  $a->{"zeroconf-port"} = \${$a->{"autoplay"}};
  $a;
[24-04-05 09:13:02.9015] Plugins::Spotty::Helper::_findBin (195) Found helper application: /config/lms/cache/InstalledPlugins/Plugins/Spotty/Bin/aarch64-linux/spotty
[24-04-05 09:13:02.9106] Plugins::Spotty::Plugin::updateTranscodingTable (274) TMPDIR=/config/lms/cache/spotty [spotty] --ap-port=12321  -n Squeezebox -c "/config/lms/cache/spotty/96ad2177" --single-track $URL$ --bitrate 320 --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 -
[24-04-05 09:13:02.9108] Plugins::Spotty::Plugin::updateTranscodingTable (274) TMPDIR=/config/lms/cache/spotty [spotty] --ap-port=12321  -n Squeezebox -c "/config/lms/cache/spotty/96ad2177" --single-track $URL$ --bitrate 320 --disable-discovery --disable-audio-cache --pass-through $START$
[24-04-05 09:13:02.9109] Plugins::Spotty::Plugin::updateTranscodingTable (274) TMPDIR=/config/lms/cache/spotty [spotty] --ap-port=12321  -n Squeezebox -c "/config/lms/cache/spotty/96ad2177" --single-track $URL$ --bitrate 320 --disable-discovery --disable-audio-cache $START$
[24-04-05 09:13:02.9110] Plugins::Spotty::Plugin::updateTranscodingTable (274) TMPDIR=/config/lms/cache/spotty [spotty] --ap-port=12321  -n Squeezebox -c "/config/lms/cache/spotty/96ad2177" --single-track $URL$ --bitrate 320 --disable-discovery --disable-audio-cache $START$ | [lame] -r --silent -q $QUALITY$ $BITRATE$ - -
[24-04-05 09:13:03.5713] Slim::Networking::IO::Select::__ANON__ (130) Error: Select task failed calling Slim::Networking::Slimproto::client_readable: Can't use string ("1") as a symbol ref while "strict refs" in use at /usr/share/perl5/Slim/Networking/IO/Select.pm line 152.
; fh=IO::Socket::INET=GLOB(0x55b4214aa8)
[24-04-05 09:13:03.5724] Slim::Networking::IO::Select::__ANON__ (130) Error: Select task failed calling Slim::Networking::Slimproto::client_readable: Can't use string ("1") as a symbol ref while "strict refs" in use at /usr/share/perl5/Slim/Networking/IO/Select.pm line 152.
; fh=IO::Socket::INET=GLOB(0x55b056bc40)
[24-04-05 09:13:05.6269] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons...
[24-04-05 09:13:06.8250] Slim::Networking::IO::Select::__ANON__ (130) Error: Select task failed calling Slim::Networking::Slimproto::client_readable: Can't use string ("1") as a symbol ref while "strict refs" in use at /usr/share/perl5/Slim/Networking/IO/Select.pm line 152.
; fh=IO::Socket::INET=GLOB(0x55b4c0b9c8)
[24-04-05 09:13:07.2860] Slim::Networking::IO::Select::__ANON__ (130) Error: Select task failed calling Slim::Networking::Slimproto::client_readable: Can't use string ("1") as a symbol ref while "strict refs" in use at /usr/share/perl5/Slim/Networking/IO/Select.pm line 152.
; fh=IO::Socket::INET=GLOB(0x55b4b2e960)
[24-04-05 09:13:09.0905] Plugins::Spotty::OPML::__ANON__ (189) Failed to get featured playlists and/or token - do not continue
[24-04-05 09:13:09.8090] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons...
[24-04-05 09:13:45.0451] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons...

joshcomley commented 5 months ago

I completely uninstalled LMS, reinstalled it, same issue.

I then did that again but renamed the "lms" folder after deletion to ensure total deletion, and it's working.

When it works, it always takes a few seconds from clicking on the Spotty icon to it opening. When it wasn't working, it was instant failure. I feel like it somehow got its knickers in a twist and refused to try to get a token again, I just don't know why.

joshcomley commented 5 months ago

Hi, it's happened again. I have tried setting a new client ID. I've removed and re-added my user. But it just doesn't seem to try to get a new token anymore.

Attached are my full scanner.log and server.log files since a reboot just now.

scanner.log server (10).log

I suspect if I completely uninstall and reinstall LMS it will work again with the same client ID, like last time.

But it's only been five days since the last time.

Is there somewhere I can go and completely clear the Spotty cache?

Edit 1:

Should mention I have tried both username/password auth and app auth. App auth doesn't redirect the auth page but does end up with the account showing if I eventually manually go back. When this previously happened, I added an entirely different Spotify account and it still had the problem.

Edit 2:

Log after setting logging to Info for a while: server (13).log

joshcomley commented 5 months ago

I have found out some more - so my suspicion in my previous posts that the token wasn't even being attempted (hence not in the logs) was correct.

If I comment out the rate limit section here:

Then I am shown the problem in Spotty:

But why would I be exceeding the rate limit is my next question? I play one or two playlists per day - however my Spotify has a LOT of playlists in it - could this be the problem?

If I change the client ID to a new one, and leave the rate limit section commented out, I am back in action.

I suppose a hacky solution here would be to support multiple client IDs to switch between them when this happens. But I'm curious to know why my rate limit has exceeded twice in one week (although I am assuming that the last problem was the same reason).

@michaelherger what log level setting would be best to diagnose this?

My debuggy brain smells something around folders. I have a folder called Old that contains no less than 554 playlists, and this folder appears near the top. Perhaps Spotty is trying to check the contents of this folder every time and it's triggering the rate limit.

michaelherger commented 5 months ago

Yes, many playlists can be an issue. If you set plugin.spotty to INFO you'd get all the calls the plugin does (but not the result sets). You'd see that in order to get that folder of playlists we'd have to do at least a dozen requests in a very short time. Playlists might be considered expensive. Long playlists even more so.

But I don't understand why they would send you away for more than three hours?!?