MMM-Spotify
MMM-Spotify copied to clipboard
Module hanging/crashing after a period of time.
I have a HyperPixel 4 square display with a Pi Zero 2 W on the back of it. I run MMM-Spotify in the top_right place with the style set to "mini". After while the module stops responding. All other modules continue to work fine. Below is an except from the logs.
I have other MagicMirrors elsewhere in the house all with MMM-Spotify enabled and none of these hang/crash so I can only think it is something peculiar to this instance.
Can anyone assist/help please.
/home/pi/.pm2/logs/MagicMirror-error.log last 15 lines:
0|mm | [02.02.2022 20:48.27.894] [ERROR] TypeError: Cannot read properties of undefined (reading 'data')
0|mm | at Timeout._onTimeout (/home/pi/MagicMirror/modules/MMM-Spotify/Spotify.js:154:64)
0|mm | at listOnTimeout (node:internal/timers:557:17)
0|mm | at processTimers (node:internal/timers:500:7)
0|mm | [02.02.2022 20:48.27.896] [ERROR] MagicMirror will not quit, but it might be a good idea to check why this happened. Maybe no internet connection?
0|mm | [02.02.2022 20:48.27.897] [ERROR] If you think this really is an issue, please open an issue on GitHub: https://github.com/MichMich/MagicMirror/issues
0|mm | [02.02.2022 23:07.33.087] [ERROR] (node:2153) UnhandledPromiseRejectionWarning: Error: getaddrinfo EAI_AGAIN my.tado.com
0|mm | at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:71:26)
0|mm | [02.02.2022 23:07.33.088] [ERROR] (node:2153) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag --unhandled-rejections=strict
(see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 5)
0|mm | [03.02.2022 09:12.35.032] [ERROR] (node:2153) UnhandledPromiseRejectionWarning: Error: getaddrinfo EAI_AGAIN my.tado.com
0|mm | at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:71:26)
0|mm | [03.02.2022 09:12.35.034] [ERROR] (node:2153) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag --unhandled-rejections=strict
(see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 7)
0|mm | [03.02.2022 09:52.38.953] [ERROR] (node:2153) UnhandledPromiseRejectionWarning: Error: getaddrinfo EAI_AGAIN my.tado.com
0|mm | at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:71:26)
0|mm | [03.02.2022 09:52.38.954] [ERROR] (node:2153) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag --unhandled-rejections=strict
(see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 9)
Additional log info from the latest crash:
0|mm | [03.02.2022 16:57.11.594] [ERROR] [SPOTIFY - James] Failed to request API: /v1/me/player 0|mm | [03.02.2022 16:57.11.597] [ERROR] [SPOTIFY - James] Invalid request 0|mm | [03.02.2022 16:57.16.618] [ERROR] Whoops! There was an uncaught exception... 0|mm | [03.02.2022 16:57.16.640] [ERROR] TypeError: Cannot read properties of undefined (reading 'data') 0|mm | at Timeout._onTimeout (/home/pi/MagicMirror/modules/MMM-Spotify/Spotify.js:154:64) 0|mm | at listOnTimeout (node:internal/timers:557:17) 0|mm | at processTimers (node:internal/timers:500:7)
Hello. Can you please give some feedback to the following questions:
- if the error occurs after a while, does it work up until then?
- you mentioned that you are running multiple MM with MMM-Spotify, did you create an Spotify application for each of these or are you using the same for all of them?
- can you please turn on debugging via config and paste the output when the error occurs?
I have a hunch that you maybe run into API rate limits when using the same Spotify application on multiple devices.
Before I send you some logs, I am currently using a single Spotify APP to run these against. If it is a rate limiting issue then I can test by giving each screen it's own app and see if the problem recurs. Let me try and get back to you.
Thanks for the swift help.
OK, so I changed every other instance of MMM-Spotify to be "disabled: true" and restarted all the MagicMirrors. I changed the config of the problem panel to include "debug: true" and restarted the panel. After about 15-20 tracks it froze again. Below are the logs; any suggestions?:
[04.02.2022 15:53.30.706] [ERROR] [SPOTIFY - James] Failed to request API: /v1/me/player
[04.02.2022 15:53.30.710] [ERROR] [SPOTIFY - James] Invalid request
[04.02.2022 15:53.30.761] [DEBUG] [SPOTIFY - James] Request: <ref *2> Writable {
_writableState: WritableState {
objectMode: false,
highWaterMark: 16384,
finalCalled: false,
needDrain: false,
ending: false,
ended: false,
finished: false,
destroyed: false,
decodeStrings: true,
defaultEncoding: 'utf8',
length: 0,
writing: false,
corked: 0,
sync: true,
bufferProcessing: false,
onwrite: [Function: bound onwrite],
writecb: null,
writelen: 0,
afterWriteTickInfo: null,
buffered: [],
bufferedIndex: 0,
allBuffers: true,
allNoop: true,
pendingcb: 0,
constructed: true,
prefinished: false,
errorEmitted: false,
emitClose: true,
autoDestroy: true,
errored: null,
closed: false,
closeEmitted: false,
[Symbol(kOnFinished)]: []
},
_events: [Object: null prototype] {
response: [Function: handleResponse],
error: [Function: handleRequestError]
},
_eventsCount: 2,
_maxListeners: undefined,
_options: {
maxRedirects: 21,
maxBodyLength: 10485760,
protocol: 'https:',
path: '/v1/me/player?additional_types=episode,track',
method: 'GET',
headers: {
Accept: 'application/json, text/plain, */*',
Authorization: 'Bearer XXXXXXXXXX',
'User-Agent': 'axios/0.21.2'
},
agent: undefined,
agents: { http: undefined, https: undefined },
auth: undefined,
hostname: 'api.spotify.com',
port: null,
nativeProtocols: { 'http:': [Object], 'https:': [Object] },
pathname: '/v1/me/player',
search: '?additional_types=episode,track'
},
_ended: true,
_ending: true,
_redirectCount: 0,
_redirects: [],
_requestBodyLength: 0,
_requestBodyBuffers: [],
_onNativeResponse: [Function (anonymous)],
_currentRequest: <ref *1> ClientRequest {
_events: [Object: null prototype] {
response: [Function],
abort: [Function (anonymous)],
aborted: [Function (anonymous)],
connect: [Function (anonymous)],
error: [Function (anonymous)],
socket: [Function (anonymous)],
timeout: [Function (anonymous)]
},
_eventsCount: 7,
_maxListeners: undefined,
outputData: [],
outputSize: 0,
writable: true,
destroyed: false,
_last: true,
chunkedEncoding: false,
shouldKeepAlive: false,
_defaultKeepAlive: true,
useChunkedEncodingByDefault: false,
sendDate: false,
_removedConnection: false,
_removedContLen: false,
_removedTE: false,
_contentLength: 0,
_hasBody: true,
_trailer: '',
finished: true,
_headerSent: true,
_closed: false,
socket: TLSSocket {
_tlsOptions: [Object],
_secureEstablished: false,
_securePending: false,
_newSessionPending: false,
_controlReleased: true,
secureConnecting: true,
_SNICallback: null,
servername: null,
alpnProtocol: null,
authorized: false,
authorizationError: null,
encrypted: true,
_events: [Object: null prototype],
_eventsCount: 11,
connecting: false,
_hadError: true,
_parent: null,
_host: 'api.spotify.com',
_readableState: [ReadableState],
_maxListeners: undefined,
_writableState: [WritableState],
allowHalfOpen: false,
_sockname: null,
_pendingData: 'GET /v1/me/player?additional_types=episode,track HTTP/1.1\r\n' +
'Accept: application/json, text/plain, */*\r\n' +
'Authorization: Bearer XXXXXXXXXX' +
'User-Agent: axios/0.21.2\r\n' +
'Host: api.spotify.com\r\n' +
'Connection: close\r\n' +
'\r\n',
_pendingEncoding: 'latin1',
server: undefined,
_server: null,
ssl: null,
_requestCert: true,
_rejectUnauthorized: true,
parser: null,
_httpMessage: [Circular *1],
[Symbol(res)]: [TLSWrap],
[Symbol(verified)]: false,
[Symbol(pendingSession)]: null,
[Symbol(async_id_symbol)]: 66810,
[Symbol(kHandle)]: null,
[Symbol(kSetNoDelay)]: false,
[Symbol(lastWriteQueueSize)]: 0,
[Symbol(timeout)]: null,
[Symbol(kBuffer)]: null,
[Symbol(kBufferCb)]: null,
[Symbol(kBufferGen)]: null,
[Symbol(kCapture)]: false,
[Symbol(kBytesRead)]: 0,
[Symbol(kBytesWritten)]: 0,
[Symbol(connect-options)]: [Object]
},
_header: 'GET /v1/me/player?additional_types=episode,track HTTP/1.1\r\n' +
'Accept: application/json, text/plain, */*\r\n' +
'Authorization: Bearer XXXXXXXXXX' +
'User-Agent: axios/0.21.2\r\n' +
'Host: api.spotify.com\r\n' +
'Connection: close\r\n' +
'\r\n',
_keepAliveTimeout: 0,
_onPendingData: [Function: nop],
agent: Agent {
_events: [Object: null prototype],
_eventsCount: 2,
_maxListeners: undefined,
defaultPort: 443,
protocol: 'https:',
options: [Object: null prototype],
requests: [Object: null prototype] {},
sockets: [Object: null prototype],
freeSockets: [Object: null prototype] {},
keepAliveMsecs: 1000,
keepAlive: false,
maxSockets: Infinity,
maxFreeSockets: 256,
scheduling: 'lifo',
maxTotalSockets: Infinity,
totalSocketCount: 1,
maxCachedSessions: 100,
_sessionCache: [Object],
[Symbol(kCapture)]: false
},
socketPath: undefined,
method: 'GET',
maxHeaderSize: undefined,
insecureHTTPParser: undefined,
path: '/v1/me/player?additional_types=episode,track',
_ended: false,
res: null,
aborted: false,
timeoutCb: null,
upgradeOrConnect: false,
parser: null,
maxHeadersCount: null,
reusedSocket: false,
host: 'api.spotify.com',
protocol: 'https:',
_redirectable: [Circular *2],
[Symbol(kCapture)]: false,
[Symbol(kNeedDrain)]: false,
[Symbol(corked)]: 0,
[Symbol(kOutHeaders)]: [Object: null prototype] {
accept: [Array],
authorization: [Array],
'user-agent': [Array],
host: [Array]
}
},
_currentUrl: 'https://api.spotify.com/v1/me/player?additional_types=episode,track',
[Symbol(kCapture)]: false
}
[04.02.2022 15:53.30.775] [DEBUG] [SPOTIFY - James] {
url: '/v1/me/player',
method: 'get',
data: null,
headers: {
Accept: 'application/json, text/plain, */*',
Authorization: 'Bearer XXXXXXXXXX,
'User-Agent': 'axios/0.21.2'
},
params: { additional_types: 'episode,track' },
baseURL: 'https://api.spotify.com',
transformRequest: [ [Function: transformRequest] ],
transformResponse: [ [Function: transformResponse] ],
timeout: 0,
adapter: [Function: httpAdapter],
xsrfCookieName: 'XSRF-TOKEN',
xsrfHeaderName: 'X-XSRF-TOKEN',
maxContentLength: -1,
maxBodyLength: -1,
validateStatus: [Function: validateStatus],
transitional: {
silentJSONParsing: true,
forcedJSONParsing: true,
clarifyTimeoutError: false
}
}
[04.02.2022 15:53.30.777] [DEBUG] [SPOTIFY - James] Retry in 5 sec...
[04.02.2022 15:53.35.787] [ERROR] Whoops! There was an uncaught exception...
[04.02.2022 15:53.35.793] [ERROR]
TypeError: Cannot read properties of undefined (reading 'data')
at Timeout._onTimeout (/home/pi/MagicMirror/modules/MMM-Spotify/Spotify.js:154:64)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7)
[04.02.2022 15:53.35.795] [ERROR] MagicMirror will not quit, but it might be a good idea to check why this happened. Maybe no internet connection?
[04.02.2022 15:53.35.797] [ERROR] If you think this really is an issue, please open an issue on GitHub: https://github.com/MichMich/MagicMirror/issues
So, two things to notice here:
-
error.request
is set, which means that theaxios
request is not receiving any response from Spotify.error.request
is defined as:The request was made but no response was received
I do not know why that is happening on your system. One feeling would be, that the device is not capable of handling all the requests in time.
-
The problem why the module completely stops functioning, is because it references the
error.response
object while it is not set - that's a bug in the module
Solutions:
- You can try to increase the
updateInterval
config, maybe that helps your device handling all the requests - I will update the code to fix the module breaking part
I've just pushed some changes to the development
branch.
@jamesvcc can you give that branch a test run? Let me know if you don't know how to do that.
Hi, yeah - sorry, no idea how to do that but happy to help if I knew how.
Sent from my iPhone
On 19 Feb 2022, at 19:03, skuethe @.***> wrote:
I've just pushed some changes to the development branch. @jamesvcchttps://github.com/jamesvcc can you give that branch a test run? Let me know if you don't know how to do that.
— Reply to this email directly, view it on GitHubhttps://github.com/skuethe/MMM-Spotify/issues/184#issuecomment-1046084363, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AOX3ASFYWQKL7PB3GXMIIXLU37SPVANCNFSM5NO5LYLA. Triage notifications on the go with GitHub Mobile for iOShttps://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Androidhttps://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub. You are receiving this because you were mentioned.Message ID: @.***>
I`ll try from my mobile:
cd ~/MagicMirror/modules/MMM-Spotify
git checkout development
git pull
Then restart MM, f.e.:
sudo systemctl restart magicmirror
Then evaluate and look at the log files.
Been running the development branch for a bit now. Still getting crashing behaviours. Here are the logs:
0|MagicMir | [07.03.2022 13:55.11.466] [WARN] You're using a full whitelist configuration to allow for all IPs
0|MagicMir | [4130:0307/135512.830294:ERROR:viz_main_impl.cc(161)] Exiting GPU process due to errors during initialization
0|MagicMir | [4176:0307/135513.087092:ERROR:sandbox_linux.cc(376)] InitializeSandbox() called with multiple threads in process gpu-process.
0|MagicMir | [07.03.2022 14:02.11.913] [ERROR] [SPOTIFY - James] Failed to request API: /v1/me/player
0|MagicMir | [07.03.2022 14:02.11.915] [ERROR] [SPOTIFY - James] Invalid response
0|MagicMir | [07.03.2022 14:02.11.923] [ERROR] [SPOTIFY - James] Response error code: 503
0|MagicMir | [07.03.2022 14:02.11.925] [ERROR] [SPOTIFY - James] Response error text: Service Unavailable
0|MagicMir | [07.03.2022 14:05.05.160] [ERROR] [SPOTIFY - James] Failed to request API: /v1/me/player
0|MagicMir | [07.03.2022 14:05.05.162] [ERROR] [SPOTIFY - James] Invalid request
0|MagicMir | [07.03.2022 14:05.05.199] [ERROR] (node:4091) UnhandledPromiseRejectionWarning: TypeError: Cannot read properties of undefined (reading 'status')
0|MagicMir | at /home/pi/MagicMirror/modules/MMM-Spotify/Spotify.js:154:55
0|MagicMir | at runMicrotasks (electron --trace-warnings ...
to show where the warning was created)
0|MagicMir | [07.03.2022 14:05.05.200] [ERROR] (node:4091) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag --unhandled-rejections=strict
(see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 3)
Latest log output (still crashing):
[08.03.2022 13:26.04.295] [DEBUG] [SPOTIFY - James] API Response: 200 [08.03.2022 13:26.04.302] [DEBUG] [SPOTIFY - James] Token file was created [08.03.2022 13:26.04.322] [DEBUG] [SPOTIFY - James] Token will expire at: Tuesday, March 8, 2022 2:25 PM [08.03.2022 14:25.13.865] [DEBUG] [SPOTIFY - James] Refreshing Token... [08.03.2022 14:25.14.044] [DEBUG] [SPOTIFY - James] API Response: 200 [08.03.2022 14:25.14.048] [DEBUG] [SPOTIFY - James] Token file was created [08.03.2022 14:25.14.052] [DEBUG] [SPOTIFY - James] Token will expire at: Tuesday, March 8, 2022 3:24 PM [08.03.2022 15:24.22.647] [DEBUG] [SPOTIFY - James] Refreshing Token... [08.03.2022 15:24.22.789] [DEBUG] [SPOTIFY - James] API Response: 200 [08.03.2022 15:24.22.793] [DEBUG] [SPOTIFY - James] Token file was created [08.03.2022 15:24.22.796] [DEBUG] [SPOTIFY - James] Token will expire at: Tuesday, March 8, 2022 4:23 PM [08.03.2022 16:23.23.712] [DEBUG] [SPOTIFY - James] Refreshing Token... [08.03.2022 16:23.23.889] [DEBUG] [SPOTIFY - James] API Response: 200 [08.03.2022 16:23.23.895] [DEBUG] [SPOTIFY - James] Token file was created [08.03.2022 16:23.23.907] [DEBUG] [SPOTIFY - James] Token will expire at: Tuesday, March 8, 2022 5:22 PM [08.03.2022 17:22.25.144] [DEBUG] [SPOTIFY - James] Refreshing Token... [08.03.2022 17:22.25.267] [DEBUG] [SPOTIFY - James] API Response: 200 [08.03.2022 17:22.25.270] [DEBUG] [SPOTIFY - James] Token file was created [08.03.2022 17:22.25.272] [DEBUG] [SPOTIFY - James] Token will expire at: Tuesday, March 8, 2022 6:21 PM [08.03.2022 18:21.34.453] [DEBUG] [SPOTIFY - James] Refreshing Token... [08.03.2022 18:21.34.611] [DEBUG] [SPOTIFY - James] Response error data: { error: 'invalid_grant', error_description: 'User does not exist' } [08.03.2022 18:21.34.615] [DEBUG] [SPOTIFY - James] Response error headers: { date: 'Tue, 08 Mar 2022 18:21:34 GMT', 'content-type': 'application/json', 'content-length': '67', 'set-cookie': [ '__Host-device_id=AQCYbeiDOeuAgFbebzVNS5B4JhC4RKdzKJqjg_RoLa4W8siDYnN_V_T14YCzmcvPvqVZaa-qth5uwLD6LmeYL1n5sYNbyF4tcAs;Version=1;Path=/;Max-Ag e=2147483647;Secure;HttpOnly;SameSite=Lax', 'sp_tr=false;Version=1;Domain=accounts.spotify.com;Path=/;Secure;SameSite=Lax' ], 'sp-trace-id': '9dfbc577c9553c37', 'strict-transport-security': 'max-age=31536000', 'x-content-type-options': 'nosniff', vary: 'Accept-Encoding', server: 'envoy', via: 'HTTP/2 edgeproxy, 1.1 google', 'alt-svc': 'clear', connection: 'close' } [08.03.2022 18:21.34.628] [DEBUG] [SPOTIFY - James] { message: 'Request failed with status code 400', name: 'Error', description: undefined, number: undefined, fileName: undefined, lineNumber: undefined, columnNumber: undefined, stack: 'Error: Request failed with status code 400\n' + ' at createError (/home/pi/MagicMirror/modules/MMM-Spotify/node_modules/axios/lib/core/createError.js:16:15)\n' + ' at settle (/home/pi/MagicMirror/modules/MMM-Spotify/node_modules/axios/lib/core/settle.js:17:12)\n' + ' at IncomingMessage.handleStreamEnd (/home/pi/MagicMirror/modules/MMM-Spotify/node_modules/axios/lib/adapters/http.js:269:11)\n' + ' at IncomingMessage.emit (node:events:406:35)\n' + ' at endReadableNT (node:internal/streams/readable:1343:12)\n' + ' at processTicksAndRejections (node:internal/process/task_queues:83:21)', config: { url: 'https://accounts.spotify.com/api/token', method: 'post', data: 'grant_type=refresh_token&refresh_token=XXXXXX VW5M7RGDLKyjtrnTdg0o0qrxbr-s3z6O1u70', headers: { Accept: 'application/json, text/plain, /', 'Content-Type': 'application/x-www-form-urlencoded', Authorization: 'Basic XXXXX', 'User-Agent': 'axios/0.21.2', 'Content-Length': 170 }, transformRequest: [ [Function: transformRequest] ], transformResponse: [ [Function: transformResponse] ], timeout: 0, adapter: [Function: httpAdapter], xsrfCookieName: 'XSRF-TOKEN', xsrfHeaderName: 'X-XSRF-TOKEN', maxContentLength: -1, maxBodyLength: -1, validateStatus: [Function: validateStatus], transitional: { silentJSONParsing: true, forcedJSONParsing: true, clarifyTimeoutError: false } }, code: undefined } [08.03.2022 18:21.34.634] [DEBUG] [SPOTIFY - James] { url: 'https://accounts.spotify.com/api/token', method: 'post',
...skipping 1 line headers: { Accept: 'application/json, text/plain, /', 'Content-Type': 'application/x-www-form-urlencoded', Authorization: 'Basic XXXXX', 'User-Agent': 'axios/0.21.2', 'Content-Length': 170 }, transformRequest: [ [Function: transformRequest] ], transformResponse: [ [Function: transformResponse] ], timeout: 0, adapter: [Function: httpAdapter], xsrfCookieName: 'XSRF-TOKEN', xsrfHeaderName: 'X-XSRF-TOKEN', maxContentLength: -1, maxBodyLength: -1, validateStatus: [Function: validateStatus], transitional: { silentJSONParsing: true, forcedJSONParsing: true, clarifyTimeoutError: false } }