search

skuethe / MMM-Spotify

Spotify display and controller for MagicMirror
MIT License
68 stars 17 forks source link

Token.json error #159

Closed sleodc closed 3 years ago

sleodc commented 3 years ago

I've got MMM-Spotify, MMM-Assistant2Display and MMM-GoogleAssistant installed successfully and authenticated successfully. Ive got Spotify-token.json and token.json in the respective modules folder. However the MMM-spotify does not display and when I tried to run voice control with assistant2display to command Spotify (ie. SPOTIFY PLAY), I get the error [SPOTIFY: ERROR]: token.json error

It was running fine before, but when I had to change to another Spotify account with a new client ID and client secret generated, it doesn't work now. I suspect the MMM-spotify is still linking to my older Spotify account. I have already re-installed the module and re-authenticated with the new client id and secret but it still does not work. Please help thank you!

skuethe commented 3 years ago

Did you delete the token.json file before re-running the first_auth.js? If not, be sure to do that, otherwise the authentication will just be skipped.

sleodc commented 3 years ago

yes I did. I even deleted the whole module and re-install it.

skuethe commented 3 years ago

Then please enable the debug setting and paste the startup log so we can see whats going on and where it is failing.

sleodc commented 3 years ago

Sorry im not sure what is important so i took the whole thing..

sleodc commented 3 years ago

pi@raspberrypi:~/MagicMirror $ npm start

magicmirror@2.14.0 start /home/pi/MagicMirror DISPLAY="${DISPLAY:=:0}" ./node_modules/.bin/electron js/electron.js

[03.04.2021 23:41.14.289] [LOG] Starting MagicMirror: v2.14.0 [03.04.2021 23:41.14.299] [LOG] Loading config ... [03.04.2021 23:41.14.312] [LOG] Loading module helpers ... [03.04.2021 23:41.14.317] [LOG] No helper found for module: alert. [03.04.2021 23:41.14.320] [LOG] No helper found for module: clock. [03.04.2021 23:41.14.322] [LOG] No helper found for module: calendar_monthly. [03.04.2021 23:41.14.938] [LOG] Initializing new module helper ... [03.04.2021 23:41.14.941] [LOG] Module helper loaded: MMM-3Day-Forecast [03.04.2021 23:41.15.558] [LOG] Initializing new module helper ... [03.04.2021 23:41.15.561] [LOG] Module helper loaded: MMM-SG-Transport-V2 [03.04.2021 23:41.16.035] [LOG] Initializing new module helper ... [03.04.2021 23:41.16.037] [LOG] Module helper loaded: MMM-Screencast [03.04.2021 23:41.16.751] [LOG] Initializing new module helper ... [03.04.2021 23:41.16.753] [LOG] Module helper loaded: MMM-NowPlayingOnSpotify [03.04.2021 23:41.16.782] [LOG] Initializing new module helper ... [03.04.2021 23:41.16.783] [LOG] Module helper loaded: MMM-Spotify [03.04.2021 23:41.16.829] [LOG] Initializing new module helper ... [03.04.2021 23:41.16.831] [LOG] Module helper loaded: newsfeed [03.04.2021 23:41.16.980] [LOG] Initializing new module helper ... [03.04.2021 23:41.16.982] [LOG] Module helper loaded: MMM-quote-of-the-day [03.04.2021 23:41.17.340] [LOG] Initializing new module helper ... [03.04.2021 23:41.17.342] [LOG] Module helper loaded: MMM-Remote-Control [03.04.2021 23:41.17.343] [LOG] No helper found for module: MMM-StopwatchTimer. [03.04.2021 23:41.17.635] [LOG] Initializing new module helper ... [03.04.2021 23:41.17.637] [LOG] Module helper loaded: MMM-FastNotes [03.04.2021 23:41.20.874] [LOG] Initializing new module helper ... [03.04.2021 23:41.20.875] [LOG] Module helper loaded: MMM-GoogleAssistant [03.04.2021 23:41.23.064] [LOG] Initializing new module helper ... [03.04.2021 23:41.23.067] [LOG] Module helper loaded: MMM-Assistant2Display [03.04.2021 23:41.23.068] [LOG] All module helpers loaded. [03.04.2021 23:41.23.243] [LOG] Starting server on port 8080 ... [03.04.2021 23:41.23.260] [LOG] Server started ... [03.04.2021 23:41.23.261] [LOG] Connecting socket for: MMM-3Day-Forecast [03.04.2021 23:41.23.263] [LOG] MMM-3Day-Forecast helper, started... [03.04.2021 23:41.23.264] [LOG] Connecting socket for: MMM-SG-Transport-V2 [03.04.2021 23:41.23.265] [LOG] Connecting socket for: MMM-Screencast [03.04.2021 23:41.23.267] [LOG] Connecting socket for: MMM-NowPlayingOnSpotify [03.04.2021 23:41.23.269] [LOG] Connecting socket for: MMM-Spotify [03.04.2021 23:41.23.270] [LOG] Connecting socket for: newsfeed [03.04.2021 23:41.23.272] [LOG] Starting node helper for: newsfeed [03.04.2021 23:41.23.273] [LOG] Connecting socket for: MMM-quote-of-the-day [03.04.2021 23:41.23.274] [LOG] MMM-quote-of-the-day helper started [03.04.2021 23:41.23.280] [LOG] Connecting socket for: MMM-Remote-Control [03.04.2021 23:41.23.281] [LOG] Starting node helper for: MMM-Remote-Control [03.04.2021 23:41.23.301] [LOG] Connecting socket for: MMM-FastNotes [03.04.2021 23:41.23.302] [LOG] Starting module helper: MMM-FastNotes [03.04.2021 23:41.23.304] [LOG] Connecting socket for: MMM-GoogleAssistant [03.04.2021 23:41.23.305] [LOG] Connecting socket for: MMM-Assistant2Display [03.04.2021 23:41.23.307] [LOG] Sockets connected & modules started ... [03.04.2021 23:41.23.719] [LOG] Launching application. [03.04.2021 23:41.23.761] [WARN] (electron) The default value of app.allowRendererProcessReuse is deprecated, it is currently "false". It will change to be "true" in Electron 9. For more information please check https://github.com/electron/electron/issues/18397 [03.04.2021 23:41.30.528] [LOG] Create new news fetcher for url: http://www.channelnewsasia.com/rssfeeds/8395986 - Interval: 300000 [03.04.2021 23:41.30.614] [LOG] Create new news fetcher for url: http://www.channelnewsasia.com/rssfeeds/8396082 - Interval: 300000 [03.04.2021 23:41.30.617] [LOG] Create new news fetcher for url: http://www.channelnewsasia.com/rssfeeds/8395954 - Interval: 300000 [03.04.2021 23:41.30.620] [LOG] Create new news fetcher for url: http://www.channelnewsasia.com/rssfeeds/8395884 - Interval: 300000 [03.04.2021 23:41.30.623] [LOG] MMM-quote-of-the-day received a socket notification: INIT_HELPER - Payload: [object Object] [03.04.2021 23:41.30.624] [LOG] MMM-quote-of-the-day received a socket notification: GET_QUOTE - Payload: [object Object] [03.04.2021 23:41.30.689] [LOG] [GA] MMM-GoogleAssistant Version: 2.5.3 [03.04.2021 23:41.30.700] [LOG] [GA] YouTube Search Function initilized. [03.04.2021 23:41.30.716] [LOG] [GA] RECIPE_LOADED: with-MMM-TelegramBot.js [03.04.2021 23:41.30.734] [LOG] [GA] RECIPE_LOADED: with-A2DSpotify.js [03.04.2021 23:41.30.738] [LOG] [GA] Assistant2Display Server Started [03.04.2021 23:41.30.749] [LOG] [GA] Use native program (mpg321) for audio response [03.04.2021 23:41.30.751] [LOG] [SOUND] mpg321 Initialized [03.04.2021 23:41.30.756] [LOG] [NPM] Initialized v0.9.93 [03.04.2021 23:41.31.049] [LOG] [GA] Google Assistant is initialized. [03.04.2021 23:41.31.057] [LOG] [A2D] MMM-Assistant2Display Version: 2.6.0 [03.04.2021 23:41.31.064] [LOG] [INTERNET] Internet v1.0.0 Initialized... [03.04.2021 23:41.31.070] [LOG] [CAST] Cast v1.1.0 Initialized... [03.04.2021 23:41.31.103] [LOG] [SPOTIFY:ERROR] Token not found! /home/pi/MagicMirror/modules/MMM-Assistant2Display/node_modules/@bugsounet/token.json [03.04.2021 23:41.31.116] [LOG] [SPOTIFY:ERROR] Token Error ! ./token.json [03.04.2021 23:41.31.120] [LOG] [SPOTIFY] Launch Librespot... [03.04.2021 23:41.31.139] [LOG] [NPM] Initialized v0.9.93 [03.04.2021 23:41.31.492] [LOG] [A2D] Assistant2Display is initialized. [03.04.2021 23:41.31.500] [ERROR] (node:25116) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. [03.04.2021 23:41.31.516] [ERROR] Whoops! There was an uncaught exception... [03.04.2021 23:41.31.529] [ERROR] Error: listen EADDRINUSE: address already in use :::8569 at Server.setupListenHandle [as _listen2] (net.js:1300:14) at listenInCluster (net.js:1348:12) at Server.listen (net.js:1436:7) at Function.listen (/home/pi/MagicMirror/modules/MMM-Assistant2Display/node_modules/express/lib/application.js:618:24) at DialServer.start (/home/pi/MagicMirror/modules/MMM-Assistant2Display/node_modules/@bugsounet/cast/index.js:90:23) at Class.addons (/home/pi/MagicMirror/modules/MMM-Assistant2Display/node_helper.js:247:17) at Class.initialize (/home/pi/MagicMirror/modules/MMM-Assistant2Display/node_helper.js:184:12) at Class.socketNotificationReceived (/home/pi/MagicMirror/modules/MMM-Assistant2Display/node_helper.js:45:14) at Socket. (/home/pi/MagicMirror/js/node_helper.js:112:11) at Socket.emit (events.js:210:5) at Socket.onevent (/home/pi/MagicMirror/node_modules/socket.io/dist/socket.js:253:20) at Socket.socket.onevent (/home/pi/MagicMirror/js/node_helper.js:105:13) at Socket._onpacket (/home/pi/MagicMirror/node_modules/socket.io/dist/socket.js:216:22) at /home/pi/MagicMirror/node_modules/socket.io/dist/client.js:205:28 at processTicksAndRejections (internal/process/task_queues.js:75:11) { code: 'EADDRINUSE', errno: 'EADDRINUSE', syscall: 'listen', address: '::', port: 8569 } [03.04.2021 23:41.31.533] [ERROR] MagicMirror will not quit, but it might be a good idea to check why this happened. Maybe no internet connection? [03.04.2021 23:41.31.535] [ERROR] If you think this really is an issue, please open an issue on GitHub: https://github.com/MichMich/MagicMirror/issues [03.04.2021 23:41.31.897] [LOG] [PM2] Connected! [03.04.2021 23:41.32.296] [ERROR] (node:25116) [DEP0066] DeprecationWarning: OutgoingMessage.prototype._headers is deprecated [03.04.2021 23:41.32.343] [LOG] Refreshed access token because it has expired. Expired at: 23:41:30 now is: 23:41:32 [03.04.2021 23:41.32.531] [LOG] { "quoteText": "No one saves us but ourselves. No one can and no one may. We ourselves must walk the path. ", "quoteAuthor": "Buddha ", "senderName": "", "senderLink": "", "quoteLink": "http://forismatic.com/en/9427cfe2f8/" } [03.04.2021 23:41.32.644] [LOG] Refreshed access token because it has expired. Expired at: 00:41:32 now is: 23:41:32 [03.04.2021 23:41.33.643] [INFO] Newsfeed-Fetcher: Broadcasting 100 items. [03.04.2021 23:41.34.215] [INFO] Newsfeed-Fetcher: Broadcasting 100 items. [03.04.2021 23:41.34.250] [LOG] Refreshed access token because it has expired. Expired at: 00:41:32 now is: 23:41:34 [03.04.2021 23:41.34.302] [ERROR] Whoops! There was an uncaught exception... [03.04.2021 23:41.34.306] [ERROR] PythonShellError: OSError: [Errno 98] Address already in use at PythonShell.parseError (/home/pi/MagicMirror/node_modules/python-shell/index.js:295:21) at terminateIfNeeded (/home/pi/MagicMirror/node_modules/python-shell/index.js:190:32) at ChildProcess. (/home/pi/MagicMirror/node_modules/python-shell/index.js:182:13) at ChildProcess.emit (events.js:210:5) at Process.ChildProcess._handle.onexit (internal/child_process.js:272:12) ----- Python Traceback ----- File "modules/MMM-FastNotes/FastNotes.py", line 25, in main() File "modules/MMM-FastNotes/FastNotes.py", line 21, in main raise e File "modules/MMM-FastNotes/FastNotes.py", line 17, in main start(host=args.host, port=args.port, debug=args.debug) File "/home/pi/MagicMirror/modules/MMM-FastNotes/backend/fast_notes.py", line 72, in start app.run(host, port, debug) File "/usr/lib/python3/dist-packages/flask/app.py", line 943, in run run_simple(host, port, self, options) File "/usr/lib/python3/dist-packages/werkzeug/serving.py", line 814, in run_simple inner() File "/usr/lib/python3/dist-packages/werkzeug/serving.py", line 774, in inner fd=fd) File "/usr/lib/python3/dist-packages/werkzeug/serving.py", line 660, in make_server passthrough_errors, ssl_context, fd=fd) File "/usr/lib/python3/dist-packages/werkzeug/serving.py", line 577, in init self.address_family), handler) File "/usr/lib/python3.7/socketserver.py", line 452, in init self.server_bind() File "/usr/lib/python3.7/http/server.py", line 137, in server_bind socketserver.TCPServer.server_bind(self) File "/usr/lib/python3.7/socketserver.py", line 466, in server_bind self.socket.bind(self.server_address) { traceback: 'Traceback (most recent call last):\n' + ' File "modules/MMM-FastNotes/FastNotes.py", line 25, in \n' + ' main()\n' + ' File "modules/MMM-FastNotes/FastNotes.py", line 21, in main\n' + ' raise e\n' + ' File "modules/MMM-FastNotes/FastNotes.py", line 17, in main\n' + ' start(host=args.host, port=args.port, debug=args.debug)\n' + ' File "/home/pi/MagicMirror/modules/MMM-FastNotes/backend/fast_notes.py", line 72, in start\n' + ' app.run(host, port, debug)\n' + ' File "/usr/lib/python3/dist-packages/flask/app.py", line 943, in run\n' + ' run_simple(host, port, self, options)\n' + ' File "/usr/lib/python3/dist-packages/werkzeug/serving.py", line 814, in run_simple\n' + ' inner()\n' + ' File "/usr/lib/python3/dist-packages/werkzeug/serving.py", line 774, in inner\n' + ' fd=fd)\n' + ' File "/usr/lib/python3/dist-packages/werkzeug/serving.py", line 660, in make_server\n' + ' passthrough_errors, ssl_context, fd=fd)\n' + ' File "/usr/lib/python3/dist-packages/werkzeug/serving.py", line 577, in init\n' + ' self.address_family), handler)\n' + ' File "/usr/lib/python3.7/socketserver.py", line 452, in init\n' + ' self.server_bind()\n' + ' File "/usr/lib/python3.7/http/server.py", line 137, in server_bind\n' + ' socketserver.TCPServer.server_bind(self)\n' + ' File "/usr/lib/python3.7/socketserver.py", line 466, in server_bind\n' + ' self.socket.bind(self.server_address)\n' + 'OSError: [Errno 98] Address already in use\n', executable: 'python3', options: null, script: 'modules/MMM-FastNotes/FastNotes.py', args: [ '--host', '192.168.10.143', '--port', 5000 ], exitCode: 1 } [03.04.2021 23:41.34.312] [ERROR] MagicMirror will not quit, but it might be a good idea to check why this happened. Maybe no internet connection? [03.04.2021 23:41.34.315] [ERROR] If you think this really is an issue, please open an issue on GitHub: https://github.com/MichMich/MagicMirror/issues [03.04.2021 23:41.34.583] [LOG] [PM2] Librespot started ! [03.04.2021 23:41.34.863] [INFO] Newsfeed-Fetcher: Broadcasting 100 items. [03.04.2021 23:41.35.372] [INFO] Newsfeed-Fetcher: Broadcasting 100 items. [03.04.2021 23:41.40.859] [LOG] [SPOTIFY:ERROR] Token Error ! ./token.json [03.04.2021 23:41.49.820] [LOG] Shutting down server... [03.04.2021 23:41.49.822] [LOG] Stopping module helper: MMM-3Day-Forecast [03.04.2021 23:41.49.824] [LOG] Stopping module helper: MMM-SG-Transport-V2 [03.04.2021 23:41.49.826] [LOG] Stopping module helper: MMM-Screencast [03.04.2021 23:41.49.828] [LOG] Stopping module helper: MMM-NowPlayingOnSpotify [03.04.2021 23:41.49.829] [LOG] Stopping module helper: MMM-Spotify [03.04.2021 23:41.49.830] [LOG] Stopping module helper: newsfeed [03.04.2021 23:41.49.832] [LOG] Stopping module helper: MMM-quote-of-the-day [03.04.2021 23:41.49.834] [LOG] Stopping module helper: MMM-FastNotes [03.04.2021 23:41.49.836] [LOG] Stopping module helper: MMM-GoogleAssistant [03.04.2021 23:41.49.838] [LOG] Stopping module helper: MMM-Assistant2Display

skuethe commented 3 years ago

Okay, pretty messy there.

First off, it seems you have another instance of MM² running, or there are some ghost processes running on your device (multiple port binds fail, because the port is already in use - MMM-Assistant2Display f.e.). Try to reboot the device to have a clean status.

Second these Spotify error messages are mixed up. For whatever reason MMM-Assistant2Display is also sending [SPOTIFY:ERROR] messages. All these lines seem to come from that particular module:

[03.04.2021 23:41.31.103] [LOG] [SPOTIFY:ERROR] Token not found! /home/pi/MagicMirror/modules/MMM-Assistant2Display/node_modules/@bugsounet/token.json
[03.04.2021 23:41.31.116] [LOG] [SPOTIFY:ERROR] Token Error ! ./token.json
[03.04.2021 23:41.31.120] [LOG] [SPOTIFY] Launch Librespot...

Taking a look at that module, something pops out:

  • MMM-Spotify module or useIntegred version but do not use both at the same time!

If you want to use MMM-Spotify you need to set useIntegred config option of the MMM-Assistant2Display module to false. Otherwise keep Spotify from that Assistant2Display module and remove MMM-Spotify. You should only run one.

Besides from that, it seems that MMM-Spotify is not even loading. Probably because of the latest version requirement from this module. To run the latest version 2.0.2 of MMM-Spotify you need to update MM² to version 2.15.0. You are running 2.14.0:

[03.04.2021 23:41.14.289] [LOG] Starting MagicMirror: v2.14.0

Verify MMM-Spotify version by searching for the line containting "version" in this file:

/home/pi/MagicMirror/modules/MMM-Spotify/package.json

If it says:

{
  "name": "MMM-Spotify",
  "version": "2.0.2",
[...]

you should update MM². Alternatively you could switch to version 2.0.1 of MMM-Spotify but that is not recommended, as you then will not be getting any automated updates in the future.

sleodc commented 3 years ago

Yes it works now! Thank you so much 🙏🏻