search

michaelherger / Spotty-Plugin

A Spotify plugin for the Lyrion Music Server (fka. Logitech Media Server) and Squeezebox compatible players
117 stars 20 forks source link

LMS 8.0.1 Library rescan failed due error shown by spotty #31

Closed NorfolkXX closed 11 months ago

NorfolkXX commented 3 years ago

Hi,

my LMS 8.0.1 on ubuntu 20.04 cannot rescan the library recently, the error message from scanner.log seems to indicate the Spotty-Plugin:

[21-01-03 09:27:51.8591] Slim::Music::Import::runImporter (577) Starting Plugins::Spotty::Importer scan [21-01-03 09:27:52.5699] main::main (338) Error: Failed when running main scan: [Can't use string ("Aborted (core dumped)") as a HASH ref while "strict refs" in use at /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/API/Token.pm line 141. ] [21-01-03 09:27:52.5702] main::main (339) Error: Skipping post-process & Not updating lastRescanTime!

Spotty v.4.4.6

michaelherger commented 3 years ago

Thanks for this report! Is Spotty working in general? To work around this issue until I have a fix you could disable Spotty integration into your library.

NorfolkXX commented 3 years ago

I removed all (2) accounts I formerly used from the spotty-plugin-config but did not disable the plugin itself.

This helped, so I could rescan the library now without issues.

I assume, the issue is connected to those accounts I had enlisted and used the plugin with LMS 7.9.1 on Ubuntu 16.04 about 1 year ago. Back then it ran perfectly without an issues. I keep plugins updated, but had no use or access to spotify to check if the plugin is working since. Recently I upgraded to Ubuntu 20.04 and LMS 8.0.1. Unfortunately, I cannot test if they work, as the spotify-accounts are used by friends and I dont have direct access. In any case, I have posted the relevant log below. Please note that the username and the connect-ID were obfuscated.

PS: Thx for your great work on LMS!!

` server.log:

[20-12-23 12:17:31.4063] main::init (388) Starting Logitech Media Server (v8.0.1, 1608617100, Tue Dec 22 07:19:05 CET 2020) perl 5.030000 - x86_64-linux-gnu-thread-multi [20-12-23 13:21:37.6742] Plugins::Spotty::API::ANON (1476) API call: me [20-12-23 13:21:37.6746] Plugins::Spotty::API::ANON (1480) error: 429 unknown [20-12-23 13:21:37.6750] Plugins::Spotty::API::error429 (1538) Zugriffsrate überschritten für: me; nächster Versuch in 5 Sekunden. [20-12-23 14:22:54.0228] Plugins::Spotty::API::Token::_killTokenHelper (177) Token refresh call helper has closed unexpectedly? - Please consider re-setting your Spotify credentials should this happen all the time. [20-12-23 14:22:55.0435] Plugins::Spotty::API::Token::_killTokenHelper (177) Token refresh call helper has closed unexpectedly? - Please consider re-setting your Spotify credentials should this happen all the time. [20-12-23 14:22:56.0645] Plugins::Spotty::API::Token::_killTokenHelper (177) Token refresh call helper has closed unexpectedly? - Please consider re-setting your Spotify credentials should this happen all the time. [20-12-23 15:30:00.6336] Plugins::Spotty::API::ANON (1476) API call: users/xxxxx/playlists?limit=50 [20-12-23 15:30:00.6339] Plugins::Spotty::API::ANON (1480) error: 429 unknown [20-12-23 15:30:00.6345] Plugins::Spotty::API::error429 (1538) Zugriffsrate überschritten für: users/xxxxx/playlists?limit=50; nächster Versuch in 12 Sekunden. [20-12-23 16:30:00.6321] Plugins::Spotty::API::ANON (1476) API call: users/xxxxx/playlists?limit=50 [20-12-23 16:30:00.6325] Plugins::Spotty::API::ANON (1480) error: 429 unknown [20-12-23 16:30:00.6330] Plugins::Spotty::API::error429 (1538) Zugriffsrate überschritten für: users/xxxxx/playlists?limit=50; nächster Versuch in 12 Sekunden.

(...)

Track Changed or Timer Fired

[20-12-31 01:53:50.4518] Slim::Utils::Misc::pathFromFileURL (225) Error: Path isn't a file URL: spotify://connect-1234567890123 [20-12-31 01:53:50.4520] Slim::Utils::Misc::pathFromFileURL (225) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Utils/Misc.pm line 225) frame 1: Slim::Utils::Misc::pathFromFileURL (/usr/share/squeezeboxserver/Plugins/SugarCube/Plugin.pm line 271) frame 2: Plugins::SugarCube::Plugin::kickoff (/usr/share/squeezeboxserver/Plugins/SugarCube/Plugin.pm line 521) frame 3: Plugins::SugarCube::Plugin::SugarDelay (/usr/share/perl5/Slim/Utils/Timers.pm line 265) frame 4: (eval) (/usr/share/perl5/Slim/Utils/Timers.pm line 265) frame 5: Slim::Utils::Timers::ANON (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167) frame 6: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167) frame 7: Slim::Networking::IO::Select::loop (/usr/sbin/squeezeboxserver line 722) frame 8: main::idle (/usr/sbin/squeezeboxserver line 678) frame 9: main::main (/usr/sbin/squeezeboxserver line 1211)

[20-12-31 01:53:50.4523] Plugins::SugarCube::Breakout::TrackTracker (328) Insert into Database Playing Track: file://spotify://connect-1234567890123 [20-12-31 01:53:50.7957] Plugins::SugarCube::Plugin::ArrayLoop (670)

Built URL Request for MusicIP:

http://localhost:10002/api/mix?&sizetype=tracks&size=10&song%3dspotify%3A%2F%2Fconnect-1234567890123&style=148&variety=0

[20-12-31 01:53:50.9099] Plugins::SugarCube::Plugin::gotErrorContinue (631)

MUSICIP FAILED

[20-12-31 01:53:50.9101] Plugins::SugarCube::Plugin::gotErrorContinue (632) MUSICIP RETURNED NOTHING Check API Service is Running [20-12-31 01:53:50.9102] Plugins::SugarCube::Plugin::gotErrorContinue (633)

MUSICIP FAILED

[20-12-31 01:53:50.9109] Plugins::SugarCube::Plugin::gotErrorContinue (635) Keeping music playing requesting (from LMS) a Random Track matching the Current Playing Tracks Genre [20-12-31 01:53:50.9115] Plugins::SugarCube::Plugin::randompuller (486) LMS Reported Track Playing; spotify://connect-1234567890123 [20-12-31 01:53:50.9122] Plugins::SugarCube::Plugin::randompuller (490) Currently Playing; spotify://connect-1234567890123 [20-12-31 01:53:50.9124] Plugins::SugarCube::Plugin::randompuller (491) Currently Playing Genre; [20-12-31 01:53:50.9125] Plugins::SugarCube::Breakout::getRandom (20) Get Random Track but block Artist 0 plus 0 plus 0 [20-12-31 01:53:50.9236] Plugins::SugarCube::Plugin::randompuller (494) Insert into Database: by [20-12-31 01:53:51.4324] Slim::Schema::objectForUrl (810) Error: Null track request! Returning undef. [20-12-31 01:53:51.4327] Slim::Schema::objectForUrl (810) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Schema.pm line 810) frame 1: Slim::Schema::objectForUrl (/usr/share/perl5/Slim/Schema/ResultSet/Track.pm line 44) frame 2: Slim::Schema::ResultSet::Track::objectForUrl (/usr/share/squeezeboxserver/Plugins/SugarCube/Plugin.pm line 512) frame 3: Plugins::SugarCube::Plugin::randompuller (/usr/share/squeezeboxserver/Plugins/SugarCube/Plugin.pm line 636) frame 4: Plugins::SugarCube::Plugin::gotErrorContinue (/usr/share/squeezeboxserver/Plugins/SugarCube/Plugin.pm line 626) frame 5: Plugins::SugarCube::Plugin::gotErrorViaHTTP (/usr/share/perl5/Slim/Networking/SimpleAsyncHTTP.pm line 116) frame 6: Slim::Networking::SimpleAsyncHTTP::onError (/usr/share/perl5/Slim/Networking/Async/HTTP.pm line 361) frame 7: Slim::Networking::Async::HTTP::_http_error (/usr/share/perl5/Slim/Networking/Async/HTTP.pm line 423) frame 8: Slim::Networking::Async::HTTP::_http_read (/usr/share/perl5/Slim/Networking/Async.pm line 282) frame 9: Slim::Networking::Async::_async_read (/usr/share/perl5/Slim/Networking/IO/Select.pm line 122) frame 10: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 118) frame 11: Slim::Networking::IO::Select::ANON (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167) frame 12: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 167) frame 13: Slim::Networking::IO::Select::loop (/usr/sbin/squeezeboxserver line 728) frame 14: main::idle (/usr/sbin/squeezeboxserver line 678) frame 15: main::main (/usr/sbin/squeezeboxserver line 1211)

[20-12-31 01:53:51.4329] Plugins::SugarCube::Plugin::gotErrorContinue (662) No Playing Track was usable [20-12-31 01:53:51.4330] Plugins::SugarCube::Plugin::gotErrorContinue (663) spotify://connect-1234567890123 [20-12-31 01:53:51.5177] Plugins::Spotty::Connect::DaemonManager::checkAPIConnectPlayers (208) Connect daemon is running, but not connected - shutting down to force restart: 00:05:22:21:ed:27 Squeezebox Touch [20-12-31 01:53:51.6502] Plugins::SugarCube::Plugin::commandCallback (716) We Paused :(

(...)

[20-12-31 01:54:28.8431] Plugins::Spotty::API::ANON (1424) API call: me/player/devices [20-12-31 01:54:28.8433] Plugins::Spotty::API::ANON (1428) error: 429 unknown [20-12-31 01:54:28.8528] Plugins::Spotty::API::error429 (1486) Zugriffsrate überschritten für: me/player/devices; nächster Versuch in 14 Sekunden.

`

NorfolkXX commented 3 years ago

Here's a update to the log posted above:

I could verify now that the references in the log about username and connect-ID, as well as the requested/played song at 31.12./01:53 was indeed to a valid account and a valid song-request from that spotify-account during that night.

And yes, this also confirms that my spotty is working and the timeout-messages above seem only to indicate that sometimes the LMS/spotty could not connect to that user. (BTW: It's a friend with spotify on his mobile phone, so maybe just unreachable for a while.)

I mentioned another spotify-account, but that one was canceled ages ago and just was never removed from the settings. In the log, there was no indication about this other account, so I dont know which of those 2 caused the issues.

With boths accounts removed from spotty now, LMS seems all OK again - except that there are no spotify-accounts but then I dont have use for spotify atm and also no premium account available for further testing myself.

michaelherger commented 11 months ago

Is this still an issue?

NorfolkXX commented 11 months ago

I dont know. After both spotify-accounts were removed as mentioned, the LMS did work again without that error and it still does. but since then I had no spotify accounts to test this situation again.

Let's close it and I come back if it occures again?