Mar 26 16:31:07 scheckspi go-librespot[1673]: time="2026-03-26T16:31:07-05:00" level=trace msg="sent dealer ping" Mar 26 16:31:07 scheckspi go-librespot[1673]: time="2026-03-26T16:31:07-05:00" level=trace msg="received dealer pong" Mar 26 16:31:12 scheckspi systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories... Mar 26 16:31:12 scheckspi systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully. Mar 26 16:31:12 scheckspi systemd[1]: Finished systemd-tmpfiles-clean.service - Cleanup of Temporary Directories. Mar 26 16:31:12 scheckspi systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dclean.service.mount: Deactivated successfully. Mar 26 16:31:22 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:22 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 3 Mar 26 16:31:22 scheckspi volumio[1314]: info: Prefetching next song Mar 26 16:31:22 scheckspi volumio[1314]: info: [1774560682117] ControllerSpotify::prefetch Mar 26 16:31:22 scheckspi volumio[1314]: info: Sending Spotify command with payload to local API: /player/add_to_queue Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=trace msg="prefetch as soon as possible" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=debug msg="prefetching next track" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=debug msg="selected format OGG_VORBIS_320 (a64ba50aff8281cf0278711cab4208c1b6dc89b5)" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=debug msg="requested aes key for file a64ba50aff8281cf0278711cab4208c1b6dc89b5, gid: 0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=debug msg="fetched first chunk of 15, total size is 7364360 bytes" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=info msg="prefetched track \"Blood On My Jeans\" (duration: 154767ms)" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:22 scheckspi go-librespot[1673]: time="2026-03-26T16:31:22-05:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:25 scheckspi go-librespot[1673]: time="2026-03-26T16:31:25-05:00" level=trace msg="emitting websocket event: not_playing" Mar 26 16:31:25 scheckspi go-librespot[1673]: time="2026-03-26T16:31:25-05:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:25 scheckspi volumio[1314]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:6wQlQrTY5mVS8EGaFZVwVF","uri":"spotify:track:6wQlQrTY5mVS8EGaFZVwVF","play_origin":"go-librespot"}} Mar 26 16:31:25 scheckspi volumio[1314]: error: Failed to decode event: not_playing Mar 26 16:31:25 scheckspi go-librespot[1673]: time="2026-03-26T16:31:25-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 16:31:25 scheckspi go-librespot[1673]: time="2026-03-26T16:31:25-05:00" level=trace msg="emitting websocket event: will_play" Mar 26 16:31:25 scheckspi go-librespot[1673]: time="2026-03-26T16:31:25-05:00" level=info msg="loaded track \"Blood On My Jeans\" (paused: false, position: 0ms, duration: 154767ms, prefetched: true)" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:25 scheckspi volumio[1314]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:6wQlQrTY5mVS8EGaFZVwVF","uri":"spotify:track:0fCwrjKfWxF3xQhZrYUw4T","play_origin":"go-librespot"}} Mar 26 16:31:26 scheckspi go-librespot[1673]: time="2026-03-26T16:31:26-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 16:31:26 scheckspi go-librespot[1673]: time="2026-03-26T16:31:26-05:00" level=trace msg="scheduling prefetch in 125s" Mar 26 16:31:26 scheckspi go-librespot[1673]: time="2026-03-26T16:31:26-05:00" level=trace msg="emitting websocket event: metadata" Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0fCwrjKfWxF3xQhZrYUw4T","name":"Blood On My Jeans","artist_names":["Juice WRLD"],"album_name":"Legends Never Die","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023e0698e4ae5ffb82a005aeeb","position":0,"duration":154767,"release_date":"year:2020 month:7 day:10","track_number":6,"disc_number":1}} Mar 26 16:31:26 scheckspi go-librespot[1673]: time="2026-03-26T16:31:26-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 16:31:26 scheckspi go-librespot[1673]: time="2026-03-26T16:31:26-05:00" level=trace msg="emitting websocket event: playing" Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:6wQlQrTY5mVS8EGaFZVwVF","uri":"spotify:track:0fCwrjKfWxF3xQhZrYUw4T","resume":false,"play_origin":"go-librespot"}} Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: PUSH STATE SPOTIFY Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: {"status":"play","service":"spop","title":"Blood On My Jeans","artist":"Juice WRLD","album":"Legends Never Die","albumart":"https://i.scdn.co/image/ab67616d00001e023e0698e4ae5ffb82a005aeeb","uri":"spotify:track:0fCwrjKfWxF3xQhZrYUw4T","trackType":"spotify","seek":0,"duration":154,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::servicePushState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Blood On My Jeans","artist":"Juice WRLD","album":"Legends Never Die","albumart":"https://i.scdn.co/image/ab67616d00001e023e0698e4ae5ffb82a005aeeb","uri":"spotify:track:0fCwrjKfWxF3xQhZrYUw4T","trackType":"spotify","seek":0,"duration":154,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 26 16:31:26 scheckspi volumio[1314]: verbose: CURRENT POSITION 2 Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreStateMachine::syncState stateService play Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreStateMachine::syncState currentStatus play Mar 26 16:31:26 scheckspi volumio[1314]: info: Received an update from plugin. extracting info from payload Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreStateMachine::pushState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::volumioPushState Mar 26 16:31:26 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:31:26 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::volumioGetState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreStateMachine::pushState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::volumioPushState Mar 26 16:31:26 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:31:26 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::volumioGetState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: SPOTIFY VOLUME 51 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: VOLUMIO VOLUME 50 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: SPOTIFY VOLUME 51 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: VOLUMIO VOLUME 50 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: PUSH STATE SPOTIFY Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: {"status":"play","service":"spop","title":"Blood On My Jeans","artist":"Juice WRLD","album":"Legends Never Die","albumart":"https://i.scdn.co/image/ab67616d00001e023e0698e4ae5ffb82a005aeeb","uri":"spotify:track:0fCwrjKfWxF3xQhZrYUw4T","trackType":"spotify","seek":1000,"duration":154,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::servicePushState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Blood On My Jeans","artist":"Juice WRLD","album":"Legends Never Die","albumart":"https://i.scdn.co/image/ab67616d00001e023e0698e4ae5ffb82a005aeeb","uri":"spotify:track:0fCwrjKfWxF3xQhZrYUw4T","trackType":"spotify","seek":1000,"duration":154,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Mar 26 16:31:26 scheckspi volumio[1314]: verbose: CURRENT POSITION 2 Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreStateMachine::syncState stateService play Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreStateMachine::syncState currentStatus play Mar 26 16:31:26 scheckspi volumio[1314]: info: Received an update from plugin. extracting info from payload Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreStateMachine::pushState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::volumioPushState Mar 26 16:31:26 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:31:26 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::volumioGetState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreStateMachine::pushState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::volumioPushState Mar 26 16:31:26 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:31:26 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreCommandRouter::volumioGetState Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 2 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: SPOTIFY VOLUME 51 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: VOLUMIO VOLUME 50 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: SPOTIFY VOLUME 51 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: VOLUMIO VOLUME 50 Mar 26 16:31:26 scheckspi volumio[1314]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 26 16:31:26 scheckspi volumio[1314]: info: CoreStateMachine::startPlaybackTimer Mar 26 16:31:26 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 3 Mar 26 16:31:27 scheckspi volumio[1314]: info: CoreStateMachine::pushState Mar 26 16:31:27 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 3 Mar 26 16:31:27 scheckspi volumio[1314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 26 16:31:27 scheckspi volumio[1314]: info: CoreCommandRouter::volumioPushState Mar 26 16:31:27 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:31:27 scheckspi volumio[1314]: info: MRS: Pushing multiroomSync output Mar 26 16:31:27 scheckspi volumio[1314]: info: CoreCommandRouter::volumioGetState Mar 26 16:31:27 scheckspi volumio[1314]: info: CorePlayQueue::getTrack 3 Mar 26 16:31:27 scheckspi volumio[1314]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Mar 26 16:31:27 scheckspi volumio[1314]: SPOTIFY: SPOTIFY VOLUME 51 Mar 26 16:31:27 scheckspi volumio[1314]: SPOTIFY: VOLUMIO VOLUME 50 Mar 26 16:31:27 scheckspi volumio[1314]: SPOTIFY: DELTA VOLUME ENOUGH: false Mar 26 16:31:31 scheckspi volumio[1314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 26 16:31:31 scheckspi volumio[1314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 26 16:31:33 scheckspi volumio[1314]: info: Enabling plugin now_playing Mar 26 16:31:33 scheckspi volumio[1314]: info: Loading plugin "now_playing"... Mar 26 16:31:33 scheckspi volumio[1314]: error: !!!! WARNING !!!! Mar 26 16:31:33 scheckspi volumio[1314]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Mar 26 16:31:33 scheckspi volumio[1314]: Require stack: Mar 26 16:31:33 scheckspi volumio[1314]: - /data/plugins/user_interface/now_playing/dist/index.js Mar 26 16:31:33 scheckspi volumio[1314]: - /volumio/app/pluginmanager.js Mar 26 16:31:33 scheckspi volumio[1314]: - /volumio/app/index.js Mar 26 16:31:33 scheckspi volumio[1314]: - /volumio/index.js Mar 26 16:31:33 scheckspi volumio[1314]: error: Stack trace: Error: Cannot find module 'geo-tz' Mar 26 16:31:33 scheckspi volumio[1314]: Require stack: Mar 26 16:31:33 scheckspi volumio[1314]: - /data/plugins/user_interface/now_playing/dist/index.js Mar 26 16:31:33 scheckspi volumio[1314]: - /volumio/app/pluginmanager.js Mar 26 16:31:33 scheckspi volumio[1314]: - /volumio/app/index.js Mar 26 16:31:33 scheckspi volumio[1314]: - /volumio/index.js Mar 26 16:31:33 scheckspi volumio[1314]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Mar 26 16:31:33 scheckspi volumio[1314]: at Module._load (node:internal/modules/cjs/loader:901:27) Mar 26 16:31:33 scheckspi volumio[1314]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 26 16:31:33 scheckspi volumio[1314]: at require (node:internal/modules/helpers:130:18) Mar 26 16:31:33 scheckspi volumio[1314]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:56:34) Mar 26 16:31:33 scheckspi volumio[1314]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Mar 26 16:31:33 scheckspi volumio[1314]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Mar 26 16:31:33 scheckspi volumio[1314]: at Module.load (node:internal/modules/cjs/loader:1091:32) Mar 26 16:31:33 scheckspi volumio[1314]: at Module._load (node:internal/modules/cjs/loader:938:12) Mar 26 16:31:33 scheckspi volumio[1314]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 26 16:31:33 scheckspi volumio[1314]: at require (node:internal/modules/helpers:130:18) Mar 26 16:31:33 scheckspi volumio[1314]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Mar 26 16:31:33 scheckspi volumio[1314]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Mar 26 16:31:33 scheckspi volumio[1314]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 26 16:31:33 scheckspi volumio[1314]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Mar 26 16:31:33 scheckspi volumio[1314]: error: !!!! WARNING !!!! Mar 26 16:31:33 scheckspi volumio[1314]: info: Done. Mar 26 16:31:37 scheckspi go-librespot[1673]: time="2026-03-26T16:31:37-05:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:37 scheckspi go-librespot[1673]: time="2026-03-26T16:31:37-05:00" level=trace msg="received accesspoint ping" Mar 26 16:31:37 scheckspi go-librespot[1673]: time="2026-03-26T16:31:37-05:00" level=trace msg="received accesspoint pong ack" Mar 26 16:31:37 scheckspi go-librespot[1673]: time="2026-03-26T16:31:37-05:00" level=trace msg="sent dealer ping" Mar 26 16:31:37 scheckspi go-librespot[1673]: time="2026-03-26T16:31:37-05:00" level=trace msg="received dealer pong" Mar 26 16:31:43 scheckspi volumio[1314]: info: Enabling plugin now_playing Mar 26 16:31:43 scheckspi volumio[1314]: info: Loading plugin "now_playing"... Mar 26 16:31:43 scheckspi volumio[1314]: error: !!!! WARNING !!!! Mar 26 16:31:43 scheckspi volumio[1314]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Mar 26 16:31:43 scheckspi volumio[1314]: Require stack: Mar 26 16:31:43 scheckspi volumio[1314]: - /data/plugins/user_interface/now_playing/dist/index.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/app/pluginmanager.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/app/index.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/index.js Mar 26 16:31:43 scheckspi volumio[1314]: error: Stack trace: Error: Cannot find module 'geo-tz' Mar 26 16:31:43 scheckspi volumio[1314]: Require stack: Mar 26 16:31:43 scheckspi volumio[1314]: - /data/plugins/user_interface/now_playing/dist/index.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/app/pluginmanager.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/app/index.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/index.js Mar 26 16:31:43 scheckspi volumio[1314]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Mar 26 16:31:43 scheckspi volumio[1314]: at Module._load (node:internal/modules/cjs/loader:901:27) Mar 26 16:31:43 scheckspi volumio[1314]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 26 16:31:43 scheckspi volumio[1314]: at require (node:internal/modules/helpers:130:18) Mar 26 16:31:43 scheckspi volumio[1314]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:56:34) Mar 26 16:31:43 scheckspi volumio[1314]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Mar 26 16:31:43 scheckspi volumio[1314]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Mar 26 16:31:43 scheckspi volumio[1314]: at Module.load (node:internal/modules/cjs/loader:1091:32) Mar 26 16:31:43 scheckspi volumio[1314]: at Module._load (node:internal/modules/cjs/loader:938:12) Mar 26 16:31:43 scheckspi volumio[1314]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 26 16:31:43 scheckspi volumio[1314]: at require (node:internal/modules/helpers:130:18) Mar 26 16:31:43 scheckspi volumio[1314]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Mar 26 16:31:43 scheckspi volumio[1314]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Mar 26 16:31:43 scheckspi volumio[1314]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 26 16:31:43 scheckspi volumio[1314]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Mar 26 16:31:43 scheckspi volumio[1314]: error: !!!! WARNING !!!! Mar 26 16:31:43 scheckspi volumio[1314]: info: Error: TypeError: Cannot read properties of null (reading 'printToastMessage') Mar 26 16:31:43 scheckspi volumio[1314]: info: Enabling plugin now_playing Mar 26 16:31:43 scheckspi volumio[1314]: info: Loading plugin "now_playing"... Mar 26 16:31:43 scheckspi volumio[1314]: error: !!!! WARNING !!!! Mar 26 16:31:43 scheckspi volumio[1314]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Mar 26 16:31:43 scheckspi volumio[1314]: Require stack: Mar 26 16:31:43 scheckspi volumio[1314]: - /data/plugins/user_interface/now_playing/dist/index.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/app/pluginmanager.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/app/index.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/index.js Mar 26 16:31:43 scheckspi volumio[1314]: error: Stack trace: Error: Cannot find module 'geo-tz' Mar 26 16:31:43 scheckspi volumio[1314]: Require stack: Mar 26 16:31:43 scheckspi volumio[1314]: - /data/plugins/user_interface/now_playing/dist/index.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/app/pluginmanager.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/app/index.js Mar 26 16:31:43 scheckspi volumio[1314]: - /volumio/index.js Mar 26 16:31:43 scheckspi volumio[1314]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Mar 26 16:31:43 scheckspi volumio[1314]: at Module._load (node:internal/modules/cjs/loader:901:27) Mar 26 16:31:43 scheckspi volumio[1314]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 26 16:31:43 scheckspi volumio[1314]: at require (node:internal/modules/helpers:130:18) Mar 26 16:31:43 scheckspi volumio[1314]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:56:34) Mar 26 16:31:43 scheckspi volumio[1314]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Mar 26 16:31:43 scheckspi volumio[1314]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Mar 26 16:31:43 scheckspi volumio[1314]: at Module.load (node:internal/modules/cjs/loader:1091:32) Mar 26 16:31:43 scheckspi volumio[1314]: at Module._load (node:internal/modules/cjs/loader:938:12) Mar 26 16:31:43 scheckspi volumio[1314]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 26 16:31:43 scheckspi volumio[1314]: at require (node:internal/modules/helpers:130:18) Mar 26 16:31:43 scheckspi volumio[1314]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Mar 26 16:31:43 scheckspi volumio[1314]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Mar 26 16:31:43 scheckspi volumio[1314]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 26 16:31:43 scheckspi volumio[1314]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Mar 26 16:31:43 scheckspi volumio[1314]: error: !!!! WARNING !!!! Mar 26 16:31:43 scheckspi volumio[1314]: info: Error: TypeError: Cannot read properties of null (reading 'printToastMessage') Mar 26 16:31:47 scheckspi volumio[1314]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 16:31:47 scheckspi go-librespot[1673]: time="2026-03-26T16:31:47-05:00" level=debug msg="fetched chunk 5/14, size: 524288" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:31:50 scheckspi volumio[1314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 26 16:31:50 scheckspi volumio[1314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 26 16:31:57 scheckspi go-librespot[1673]: time="2026-03-26T16:31:57-05:00" level=debug msg="fetched chunk 6/14, size: 524288" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:32:07 scheckspi go-librespot[1673]: time="2026-03-26T16:32:07-05:00" level=debug msg="fetched chunk 7/14, size: 524288" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:32:07 scheckspi go-librespot[1673]: time="2026-03-26T16:32:07-05:00" level=trace msg="sent dealer ping" Mar 26 16:32:07 scheckspi go-librespot[1673]: time="2026-03-26T16:32:07-05:00" level=trace msg="received dealer pong" Mar 26 16:32:17 scheckspi go-librespot[1673]: time="2026-03-26T16:32:17-05:00" level=debug msg="fetched chunk 8/14, size: 524288" uri="spotify:track:0fCwrjKfWxF3xQhZrYUw4T" Mar 26 16:32:19 scheckspi su[3676]: pam_unix(su:session): session closed for user volumio Mar 26 16:32:19 scheckspi systemd[1]: session-c1.scope: Deactivated successfully. Mar 26 16:32:19 scheckspi systemd[1]: session-c1.scope: Consumed 28.110s CPU time. Mar 26 16:32:19 scheckspi volumio[1314]: info: Creating user directories (if not exist) Mar 26 16:32:19 scheckspi volumio5-onboarding[1584]: time=2026-03-26T16:32:19.807-05:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:32:19 scheckspi volumio[1314]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 26 16:32:19 scheckspi volumio[1314]: TypeError: Cannot read properties of null (reading 'broadcastMessage') Mar 26 16:32:19 scheckspi volumio[1314]: at /volumio/app/index.js:1534:32 Mar 26 16:32:19 scheckspi volumio[1314]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Mar 26 16:32:19 scheckspi volumio[1314]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Mar 26 16:32:19 scheckspi volumio[1314]: at CoreCommandRouter.broadcastMessage (/volumio/app/index.js:1532:13) Mar 26 16:32:19 scheckspi volumio[1314]: at PluginManager.pushMessage (/volumio/app/pluginmanager.js:1594:20) Mar 26 16:32:19 scheckspi volumio[1314]: at Tail. (/volumio/app/pluginmanager.js:860:24) Mar 26 16:32:19 scheckspi volumio[1314]: at Tail.emit (node:events:514:28) Mar 26 16:32:19 scheckspi volumio[1314]: at ReadStream. (/volumio/node_modules/tail/lib/tail.js:51:33) Mar 26 16:32:19 scheckspi volumio[1314]: at ReadStream.emit (node:events:514:28) Mar 26 16:32:19 scheckspi volumio[1314]: at addChunk (node:internal/streams/readable:343:12) Mar 26 16:32:19 scheckspi volumio[1314]: at readableAddChunk (node:internal/streams/readable:312:11) Mar 26 16:32:19 scheckspi volumio[1314]: at Readable.push (node:internal/streams/readable:253:10) Mar 26 16:32:19 scheckspi volumio[1314]: at node:internal/fs/streams:275:14 Mar 26 16:32:19 scheckspi volumio[1314]: at FSReqCallback.wrapper [as oncomplete] (node:fs:701:5) Mar 26 16:32:19 scheckspi volumio[1314]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 26 16:32:19 scheckspi sudo[3673]: pam_unix(sudo:session): session closed for user root Mar 26 16:32:20 scheckspi sudo[3954]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-26 16:31' Mar 26 16:32:20 scheckspi sudo[3954]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"