-- Logs begin at Sun 2025-06-29 12:29:29 CEST, end at Sun 2025-06-29 12:43:40 CEST. -- Jun 29 12:42:04 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:04+02:00" level=debug msg="fetched chunk 13/17, size: 524288" uri="spotify:track:7Dwk4YmBNSqOfRAN7MjQZK" Jun 29 12:42:16 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:16+02:00" level=debug msg="fetched chunk 14/17, size: 524288" uri="spotify:track:7Dwk4YmBNSqOfRAN7MjQZK" Jun 29 12:42:18 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:18+02:00" level=trace msg="received accesspoint ping" Jun 29 12:42:18 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:18+02:00" level=trace msg="received accesspoint pong ack" Jun 29 12:42:18 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:18+02:00" level=trace msg="sent dealer ping" Jun 29 12:42:18 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:18+02:00" level=trace msg="received dealer pong" Jun 29 12:42:27 volumio-mario volumio[848]: info: Enabling plugin now_playing Jun 29 12:42:27 volumio-mario volumio[848]: info: Loading plugin "now_playing"... Jun 29 12:42:27 volumio-mario volumio[848]: error: !!!! WARNING !!!! Jun 29 12:42:27 volumio-mario volumio[848]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Jun 29 12:42:27 volumio-mario volumio[848]: Require stack: Jun 29 12:42:27 volumio-mario volumio[848]: - /data/plugins/user_interface/now_playing/dist/index.js Jun 29 12:42:27 volumio-mario volumio[848]: - /volumio/app/pluginmanager.js Jun 29 12:42:27 volumio-mario volumio[848]: - /volumio/app/index.js Jun 29 12:42:27 volumio-mario volumio[848]: - /volumio/index.js Jun 29 12:42:27 volumio-mario volumio[848]: error: Stack trace: Error: Cannot find module 'geo-tz' Jun 29 12:42:27 volumio-mario volumio[848]: Require stack: Jun 29 12:42:27 volumio-mario volumio[848]: - /data/plugins/user_interface/now_playing/dist/index.js Jun 29 12:42:27 volumio-mario volumio[848]: - /volumio/app/pluginmanager.js Jun 29 12:42:27 volumio-mario volumio[848]: - /volumio/app/index.js Jun 29 12:42:27 volumio-mario volumio[848]: - /volumio/index.js Jun 29 12:42:27 volumio-mario volumio[848]: at Function.Module._resolveFilename (internal/modules/cjs/loader.js:931:15) Jun 29 12:42:27 volumio-mario volumio[848]: at Function.Module._load (internal/modules/cjs/loader.js:774:27) Jun 29 12:42:27 volumio-mario volumio[848]: at Module.require (internal/modules/cjs/loader.js:1003:19) Jun 29 12:42:27 volumio-mario volumio[848]: at require (internal/modules/cjs/helpers.js:107:18) Jun 29 12:42:27 volumio-mario volumio[848]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:46:34) Jun 29 12:42:27 volumio-mario volumio[848]: at Module._compile (internal/modules/cjs/loader.js:1114:14) Jun 29 12:42:27 volumio-mario volumio[848]: at Object.Module._extensions..js (internal/modules/cjs/loader.js:1143:10) Jun 29 12:42:27 volumio-mario volumio[848]: at Module.load (internal/modules/cjs/loader.js:979:32) Jun 29 12:42:27 volumio-mario volumio[848]: at Function.Module._load (internal/modules/cjs/loader.js:819:12) Jun 29 12:42:27 volumio-mario volumio[848]: at Module.require (internal/modules/cjs/loader.js:1003:19) Jun 29 12:42:27 volumio-mario volumio[848]: at require (internal/modules/cjs/helpers.js:107:18) Jun 29 12:42:27 volumio-mario volumio[848]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Jun 29 12:42:27 volumio-mario volumio[848]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Jun 29 12:42:27 volumio-mario volumio[848]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jun 29 12:42:27 volumio-mario volumio[848]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Jun 29 12:42:27 volumio-mario volumio[848]: error: !!!! WARNING !!!! Jun 29 12:42:27 volumio-mario volumio[848]: info: Done. Jun 29 12:42:28 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:28+02:00" level=debug msg="fetched chunk 15/17, size: 524288" uri="spotify:track:7Dwk4YmBNSqOfRAN7MjQZK" Jun 29 12:42:41 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:41+02:00" level=debug msg="fetched chunk 16/17, size: 524288" uri="spotify:track:7Dwk4YmBNSqOfRAN7MjQZK" Jun 29 12:42:48 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:48+02:00" level=trace msg="sent dealer ping" Jun 29 12:42:48 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:48+02:00" level=trace msg="received dealer pong" Jun 29 12:42:53 volumio-mario go-librespot[3807]: time="2025-06-29T12:42:53+02:00" level=debug msg="fetched chunk 17/17, size: 170969" uri="spotify:track:7Dwk4YmBNSqOfRAN7MjQZK" Jun 29 12:43:18 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:18+02:00" level=trace msg="sent dealer ping" Jun 29 12:43:18 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:18+02:00" level=trace msg="received dealer pong" Jun 29 12:43:35 volumio-mario volumio[848]: info: CorePlayQueue::getTrack 0 Jun 29 12:43:35 volumio-mario volumio[848]: info: CorePlayQueue::getTrack 1 Jun 29 12:43:35 volumio-mario volumio[848]: info: Prefetching next song Jun 29 12:43:35 volumio-mario volumio[848]: info: [1751193815222] ControllerSpotify::prefetch Jun 29 12:43:35 volumio-mario volumio[848]: info: Sending Spotify command with payload to local API: /player/add_to_queue Jun 29 12:43:35 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 29 12:43:35 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:35+02:00" level=debug msg="prefetching next track" uri="spotify:track:5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:35 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:35+02:00" level=debug msg="selected format OGG_VORBIS_320 (83c26ee83c3940d17459695655e31b0eb25de640)" uri="spotify:track:5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:35 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:35+02:00" level=debug msg="requested aes key for file 83c26ee83c3940d17459695655e31b0eb25de640, gid: 5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:35 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:35+02:00" level=debug msg="fetched first chunk of 10, total size is 4879792 bytes" uri="spotify:track:5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:35 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:35+02:00" level=info msg="prefetched track \"i feel lost\" (duration: 147600ms)" uri="spotify:track:5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:35 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:35+02:00" level=debug msg="fetched chunk 1/9, size: 524288" uri="spotify:track:5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:35 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:35+02:00" level=debug msg="fetched chunk 3/9, size: 524288" uri="spotify:track:5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:35 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:35+02:00" level=debug msg="fetched chunk 2/9, size: 524288" uri="spotify:track:5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:39 volumio-mario volumio[848]: info: CoreStateMachine::startPlaybackTimer Jun 29 12:43:39 volumio-mario volumio[848]: info: CorePlayQueue::getTrack 1 Jun 29 12:43:40 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:40+02:00" level=trace msg="emitting websocket event: not_playing" Jun 29 12:43:40 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:40+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:40 volumio-mario volumio[848]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:7Dwk4YmBNSqOfRAN7MjQZK","play_origin":"go-librespot"}} Jun 29 12:43:40 volumio-mario volumio[848]: error: Failed to decode event: not_playing Jun 29 12:43:40 volumio-mario volumio[848]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:7Dwk4YmBNSqOfRAN7MjQZK","play_origin":"go-librespot"}} Jun 29 12:43:40 volumio-mario volumio[848]: error: Failed to decode event: not_playing Jun 29 12:43:40 volumio-mario volumio[848]: info: CoreStateMachine::pushState Jun 29 12:43:40 volumio-mario volumio[848]: info: CorePlayQueue::getTrack 1 Jun 29 12:43:40 volumio-mario volumio[848]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 29 12:43:40 volumio-mario volumio[848]: info: CoreCommandRouter::volumioPushState Jun 29 12:43:40 volumio-mario volumio[848]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 29 12:43:40 volumio-mario volumio[848]: TypeError: Cannot read property 'pushState' of null Jun 29 12:43:40 volumio-mario volumio[848]: at /volumio/app/index.js:326:32 Jun 29 12:43:40 volumio-mario volumio[848]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Jun 29 12:43:40 volumio-mario volumio[848]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Jun 29 12:43:40 volumio-mario volumio[848]: at CoreCommandRouter.volumioPushState (/volumio/app/index.js:324:13) Jun 29 12:43:40 volumio-mario volumio[848]: at CoreStateMachine.pushState (/volumio/app/statemachine.js:530:22) Jun 29 12:43:40 volumio-mario volumio[848]: at listOnTimeout (internal/timers.js:557:17) Jun 29 12:43:40 volumio-mario volumio[848]: at processTimers (internal/timers.js:500:7) Jun 29 12:43:40 volumio-mario volumio[848]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 29 12:43:40 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 29 12:43:40 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:40+02:00" level=trace msg="emitting websocket event: will_play" Jun 29 12:43:40 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:40+02:00" level=info msg="loaded track \"i feel lost\" (paused: false, position: 0ms, duration: 147600ms, prefetched: true)" uri="spotify:track:5teI32jGP95ScDQ1T6eKUd" Jun 29 12:43:40 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 29 12:43:40 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:40+02:00" level=trace msg="scheduling prefetch in 118s" Jun 29 12:43:40 volumio-mario go-librespot[3807]: time="2025-06-29T12:43:40+02:00" level=trace msg="emitting websocket event: metadata" Jun 29 12:43:40 volumio-mario sudo[4733]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-29 12:42 Jun 29 12:43:40 volumio-mario sudo[4733]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 05:26:48 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="a63f40325536655a08b14de2b295ce76"