search

michaelherger / Spotty-Plugin

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

Failed to get access token #86

Closed bernardjeef closed 1 year ago

bernardjeef commented 1 year ago

Firstly thanks for all your efforts Michael, I really appreciate the integration.

I'm using : LMS on Squeezebox - Musical Fidelity M6 Encore 225 Spotty (V4.8.8)

Since a week or 2, i'm getting the error "Failed to get access token" when trying to connect to spotify directly from LMS or by trying to broadcast my phone spotify app to LMS.

I tried to :

Here is the error form logs : [23-04-13 00:36:50.1186] Plugins::Spotty::Connect::_connectEvent (371) Got called from spotty helper for 00:15:fe:00:03:ad: start [23-04-13 00:36:50.1228] Plugins::Spotty::API::Token::_logCommand (155) Trying to get access token: "/media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64" -n "Squeezebox" -c "/media/data/Cache/spotty/59de4dae" -i "93aac68fb06348598c1e67734dfaceee" --disable-discovery --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" --save-token "/tmp/spt-sY90bNv6" [23-04-13 00:36:50.6332] Plugins::Spotty::API::Token::_killTokenHelper (201) Token refresh call helper has closed unexpectedly? - Please consider re-setting your Spotify credentials should this continue to happen. [23-04-13 00:36:50.6360] Plugins::Spotty::Connect::ANON (413) Current Connect state: ( { name => "Failed to get access token", progress => 0, type => "text" }, "start", ) [23-04-13 00:36:50.6376] Plugins::Spotty::Connect::ANON (434) Unknown command called? start { name => "Failed to get access token", progress => 0, type => "text" } [23-04-13 00:36:54.7981] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons... [23-04-13 00:36:54.7993] Plugins::Spotty::Connect::DaemonManager::initHelpers (122) This is the sync group's master, or a standalone player with Spotify Connect enabled: 00:15:fe:00:03:ad [23-04-13 00:36:54.8005] Plugins::Spotty::Connect::DaemonManager::startHelper (147) Need to (re-)start Connect daemon for 00:15:fe:00:03:ad [23-04-13 00:36:54.8023] Plugins::Spotty::Connect::Daemon::start (90) Starting Spotty Connect daemon: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64 -c /media/data/Cache/spotty/59de4dae -n Musical Fidelity M6 Encore 225 --disable-audio-cache --bitrate 96 --player-mac 00:15:fe:00:03:ad --lms 192.168.2.177:9000 --disable-discovery --autoplay --ap-port=12321 [23-04-13 00:36:55.1079] Plugins::Spotty::Connect::_connectEvent (371) Got called from spotty helper for 00:15:fe:00:03:ad: volume [23-04-13 00:36:55.1126] Plugins::Spotty::API::Token::_logCommand (155) Trying to get access token: "/media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64" -n "Squeezebox" -c "/media/data/Cache/spotty/59de4dae" -i "93aac68fb06348598c1e67734dfaceee" --disable-discovery --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" --save-token "/tmp/spt-H1BXVgHL" [23-04-13 00:36:55.1248] Plugins::Spotty::Connect::_connectEvent (380) Ignoring initial volume reset right after daemon start [23-04-13 00:36:55.6228] Plugins::Spotty::API::Token::_killTokenHelper (201) Token refresh call helper has closed unexpectedly? - Please consider re-setting your Spotify credentials should this continue to happen. [23-04-13 00:37:54.8153] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons... [23-04-13 00:37:54.8176] Plugins::Spotty::Connect::DaemonManager::initHelpers (122) This is the sync group's master, or a standalone player with Spotify Connect enabled: 00:15:fe:00:03:ad [23-04-13 00:38:54.8208] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons... [23-04-13 00:38:54.8224] Plugins::Spotty::Connect::DaemonManager::initHelpers (122) This is the sync group's master, or a standalone player with Spotify Connect enabled: 00:15:fe:00:03:ad [23-04-13 00:39:54.8251] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons... [23-04-13 00:39:54.8264] Plugins::Spotty::Connect::DaemonManager::initHelpers (122) This is the sync group's master, or a standalone player with Spotify Connect enabled: 00:15:fe:00:03:ad [23-04-13 00:39:55.0616] Plugins::Spotty::AccountHelper::renameCacheFolder (147) Trying to rename AUTHENTICATE to [23-04-13 00:39:55.0639] Plugins::Spotty::AccountHelper::renameCacheFolder (147) Trying to rename AUTHENTICATE to [23-04-13 00:39:55.0690] Plugins::Spotty::Helper::_findBin (192) Trying helper application: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty [23-04-13 00:39:55.0982] Plugins::Spotty::Helper::_findBin (195) Found helper application: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty [23-04-13 00:39:55.1000] Plugins::Spotty::Helper::_findBin (192) Trying helper application: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64 [23-04-13 00:39:55.1316] Plugins::Spotty::Helper::_findBin (195) Found helper application: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64 [23-04-13 00:40:20.6505] Plugins::Spotty::Connect::_connectEvent (371) Got called from spotty helper for 00:15:fe:00:03:ad: start [23-04-13 00:40:20.6558] Plugins::Spotty::API::Token::get (226) Didn't find cached token. Need to refresh. [23-04-13 00:40:20.6587] Plugins::Spotty::API::Token::_logCommand (155) Trying to get access token: "/media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64" -n "Squeezebox" -c "/media/data/Cache/spotty/59de4dae" -i "93aac68fb06348598c1e67734dfaceee" --disable-discovery --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" --save-token "/tmp/spt-nMfTbt4Q" [23-04-13 00:40:20.6747] Plugins::Spotty::API::Token::get (226) Didn't find cached token. Need to refresh. [23-04-13 00:40:21.1700] Plugins::Spotty::API::Token::_killTokenHelper (201) Token refresh call helper has closed unexpectedly? - Please consider re-setting your Spotify credentials should this continue to happen. [23-04-13 00:40:21.1741] Plugins::Spotty::Connect::ANON (413) Current Connect state: ( { name => "Failed to get access token", progress => 0, type => "text" }, "start", )

thank you

michaelherger commented 1 year ago

Hi @bernardjeef - would you be able to SSH into the Encore? Or is it a closed box?

Can you check the IO::Socket::SSL version reported in Settings/Information? And the LMS version?

bernardjeef commented 1 year ago

Hi @michaelherger , It's a close box, I dont have the SSH password...

find this version in log : Starting Logitech Media Server (v7.9.1, TRUNK, UNKNOWN) perl 5.022000 - x86_64-linux

I tried somes setting by disabling the async token refress call and I think the plugin is going further... The connection seem to work and i can see the parsed response from spotify but the plugin is not working, I have 2 differents errors now.

[23-04-18 01:20:29.6785] Plugins::Spotty::Connect::Context::new (55) Create new Connect context... [23-04-18 01:20:29.6869] Plugins::Spotty::Plugin::updateTranscodingTable (270) TMPDIR=/media/data/Cache/spotty [spotty-x86_64] --ap-port=12321 -n Squeezebox -c "/media/data/Cache/spotty/59de4dae" --single-track $URL$ --bitrate 320 --disable-discovery --disable-audio-cache --pass-through $START$ [23-04-18 01:20:29.6880] Plugins::Spotty::Plugin::updateTranscodingTable (270) TMPDIR=/media/data/Cache/spotty [spotty-x86_64] --ap-port=12321 -n Squeezebox -c "/media/data/Cache/spotty/59de4dae" --single-track $URL$ --bitrate 320 --disable-discovery --disable-audio-cache $START$ [23-04-18 01:20:29.6930] Plugins::Spotty::Plugin::updateTranscodingTable (270) TMPDIR=/media/data/Cache/spotty [spotty-x86_64] --ap-port=12321 -n Squeezebox -c "/media/data/Cache/spotty/59de4dae" --single-track $URL$ --bitrate 320 --disable-discovery --disable-audio-cache $START$ | [lame] -r --silent -q $QUALITY$ $BITRATE$ - - [23-04-18 01:20:29.6943] Plugins::Spotty::Plugin::updateTranscodingTable (270) TMPDIR=/media/data/Cache/spotty [spotty-x86_64] --ap-port=12321 -n Squeezebox -c "/media/data/Cache/spotty/59de4dae" --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 - [23-04-18 01:20:29.6974] Plugins::Spotty::AccountHelper::purgeAudioCacheAfterXTracks (232) Played 7 song(s) since last audio cache purge. [23-04-18 01:20:29.7354] Plugins::Spotty::ProtocolHandler::getMetadataFor (216) No metadata found - need to look online: [23-04-18 01:20:29.7569] Slim::Networking::IO::Select::ANON (131) Error: Select task failed calling Slim::Networking::Async::HTTP::_http_read_body: Can't call method "isa" on an undefined value at /usr/encore/server/Slim/Player/Squeezebox.pm line 767. ; fh=Slim::Networking::Async::Socket::HTTPS=GLOB(0x9a787b8)

[23-04-18 01:25:13.4728] Plugins::Spotty::Settings::Auth::startHelper (163) Starting Spotty Connect deamon: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64 -c /media/data/Cache/spotty/AUTHENTICATE -n Spotify Authorization (M6 Encore) -a --ap-port=12321 [23-04-18 01:25:13.4877] Plugins::Spotty::Helper::_findBin (192) Trying helper application: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty [23-04-18 01:25:13.5207] Plugins::Spotty::Helper::_findBin (195) Found helper application: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty [23-04-18 01:25:13.5226] Plugins::Spotty::Helper::_findBin (192) Trying helper application: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64 [23-04-18 01:25:13.5531] Plugins::Spotty::Helper::_findBin (195) Found helper application: /media/data/Cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64 [23-04-18 01:25:38.2498] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons... [23-04-18 01:25:38.2520] Plugins::Spotty::Connect::DaemonManager::initHelpers (122) This is the sync group's master, or a standalone player with Spotify Connect enabled: 00:15:fe:00:03:ad [23-04-18 01:26:38.2566] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons... [23-04-18 01:26:38.2582] Plugins::Spotty::Connect::DaemonManager::initHelpers (122) This is the sync group's master, or a standalone player with Spotify Connect enabled: 00:15:fe:00:03:ad [23-04-18 01:27:38.2651] Plugins::Spotty::Connect::DaemonManager::initHelpers (92) Checking Spotty Connect helper daemons... [23-04-18 01:27:38.2674] Plugins::Spotty::Connect::DaemonManager::initHelpers (122) This is the sync group's master, or a standalone player with Spotify Connect enabled: 00:15:fe:00:03:ad [23-04-18 01:27:51.9166] Plugins::Spotty::Connect::_connectEvent (371) Got called from spotty helper for 00:15:fe:00:03:ad: start [23-04-18 01:27:51.9236] Slim::Control::Request::execute (1888) Error: While trying to run function coderef [Plugins::Spotty::Connect::_connectEvent]: [Can't call method "player" without a package or object reference at /media/data/Cache/InstalledPlugins/Plugins/Spotty/Connect.pm line 511. ] [23-04-18 01:27:51.9251] Slim::Web::JSONRPC::requestMethod (413) Request failed with error: Bad dispatch!

michaelherger commented 1 year ago

Are these two messages from after you disabled async token updates? could you please provide the system information given in LMS' Settings/Information header?

There happens to be another user(?) reporting similar failures for TIDAL in https://forums.slimdevices.com/forum/user-forums/3rd-party-hardware/1636790-musical-fidelity-encore-225-tidal-login-problem. I wonder whether some libraries on the device are outdated.

axelbusch commented 1 year ago

@bernardjeef Did you find out anything? I just wrote to musical fidelity for the second time to get any support regarding Tidal plugin. However, so far nobody answered yet. Very disappointing so far...

bernardjeef commented 1 year ago

Hi @axelbusch and @michaelherger, sorry for my late response, i did not have the time to test again since this week.

I try again broadcasting from my spotify app on my cellphone to the amp and it's back to working as before... I checked if there where any automated updates on the MF, but I see nothing... -Musical Fidelity Encore Server Version: 7.9.1 - TRUNK @ UNKNOWN -Spotty 4.8.8

I dont understand...

michaelherger commented 1 year ago

Musical Fidelity is a totally different story... worth following up about, but somewhere else. Would you know whether there's a community for it? There's no reason why it wouldn't be able to run a recent LMS 8.4.