Module hanging/crashing after a period of time.

[jamesvcc]

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)

[jamesvcc]

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)

[skuethe]

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.

[jamesvcc]

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.

[jamesvcc]

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

[skuethe]

So, two things to notice here:

1. error.request is set, which means that the axios 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.

2. 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:

1. You can try to increase the updateInterval config, maybe that helps your device handling all the requests
2. I will update the code to fix the module breaking part

[skuethe]

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.

[jamesvcc]

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: @.***>

[skuethe]

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.

[jamesvcc]

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 () 0|MagicMir | at processTicksAndRejections (node:internal/process/task_queues:96:5) 0|MagicMir | (Use 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)

[jamesvcc]

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 } }