-- Logs begin at Thu 2019-02-14 10:11:58 GMT, end at Wed 2025-04-30 12:31:13 BST. -- Apr 30 12:30:03 volumio go-librespot[1083]: time="2025-04-30T12:30:03+01:00" level=trace msg="sent dealer ping" Apr 30 12:30:03 volumio go-librespot[1083]: time="2025-04-30T12:30:03+01:00" level=trace msg="received dealer pong" Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=trace msg="emitting websocket event: not_playing" Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:0bGImSqDB2ebdeoCidUC8o","play_origin":"free-tier-artist"}} Apr 30 12:30:22 volumio volumio[856]: error: Failed to decode event: not_playing Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=error msg="failed fetching next tracks" error="failed moving to next index 10 (page 1): failed fetching page: invalid status code from page at artistplaycontext/v1/page/spotify/artist-top-tracks-extensions/2qnpHrOzdmOo1S4ox3j17x?exclude_uri=spotify:track:6ONyZXRIEiZWWnAA1F5YvH,spotify:track:0bGImSqDB2ebdeoCidUC8o,spotify:track:5iXnD2VizcAbErpkcuNQ6I,spotify:track:1dB0NylVkpjdOe8DiekIs7,spotify:track:4pV11quzVm52tULYj6ITD2,spotify:track:5D7AFGloFpXtdT2PiKTEC3,spotify:track:3zQpWQCDm9QMDaAhe4ggoO,spotify:track:69uzV9BQmNLPIu0dWK4Tbe,spotify:track:5o5SdS2vu1PgKblBABGlER,spotify:track:1Rz1CTinAymBA4dcMPGijY: 404" uri="spotify:artist:2qnpHrOzdmOo1S4ox3j17x" Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5iXnD2VizcAbErpkcuNQ6I" Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=trace msg="emitting websocket event: will_play" Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=info msg="loaded track \"MYSTERY\" (paused: false, position: 0ms, duration: 155199ms, prefetched: true)" uri="spotify:track:5iXnD2VizcAbErpkcuNQ6I" Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5iXnD2VizcAbErpkcuNQ6I","play_origin":"free-tier-artist"}} Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=trace msg="scheduling prefetch in 125s" Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=trace msg="emitting websocket event: metadata" Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5iXnD2VizcAbErpkcuNQ6I","name":"MYSTERY","artist_names":["Turnstile"],"album_name":"GLOW ON","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a4499cf37a6fe4ff043dc9f2","position":0,"duration":155199,"release_date":"year:2021 month:8 day:27","track_number":1,"disc_number":1}} Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 30 12:30:22 volumio go-librespot[1083]: time="2025-04-30T12:30:22+01:00" level=trace msg="emitting websocket event: playing" Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5iXnD2VizcAbErpkcuNQ6I","play_origin":"free-tier-artist"}} Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: PUSH STATE SPOTIFY Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: {"status":"play","service":"spop","title":"MYSTERY","artist":"Turnstile","album":"GLOW ON","albumart":"https://i.scdn.co/image/ab67616d00001e02a4499cf37a6fe4ff043dc9f2","uri":"spotify:track:5iXnD2VizcAbErpkcuNQ6I","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 30 12:30:22 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 30 12:30:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 30 12:30:22 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 30 12:30:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: PUSH STATE SPOTIFY Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: {"status":"play","service":"spop","title":"MYSTERY","artist":"Turnstile","album":"GLOW ON","albumart":"https://i.scdn.co/image/ab67616d00001e02a4499cf37a6fe4ff043dc9f2","uri":"spotify:track:5iXnD2VizcAbErpkcuNQ6I","trackType":"spotify","seek":0,"duration":155,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 30 12:30:22 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 30 12:30:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 30 12:30:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 30 12:30:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 30 12:30:33 volumio go-librespot[1083]: time="2025-04-30T12:30:33+01:00" level=trace msg="sent dealer ping" Apr 30 12:30:33 volumio go-librespot[1083]: time="2025-04-30T12:30:33+01:00" level=trace msg="received dealer pong" Apr 30 12:30:38 volumio go-librespot[1083]: time="2025-04-30T12:30:38+01:00" level=debug msg="fetched chunk 4/12, size: 524288" uri="spotify:track:5iXnD2VizcAbErpkcuNQ6I" Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 30 12:30:45 volumio volumio[856]: info: Discovery: Getting this device information Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 30 12:30:45 volumio volumio[856]: verbose: New Socket.io Connection to 192.168.0.28:3000 from 192.168.0.11 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 30 12:30:45 volumio volumio[856]: verbose: New Socket.io Connection to 192.168.0.28 from 192.168.0.11 UA: Mozilla/5.0 (Linux; Android 15; Pixel 6 Build/BP1A.250305.019; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/135.0.7049.111 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Apr 30 12:30:45 volumio volumio[856]: info: Received Get System Info Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 30 12:30:45 volumio volumio[856]: info: Discovery: Getting this device information Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: Received Get System Info Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 30 12:30:45 volumio volumio[856]: info: Discovery: Getting this device information Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetVisibleSources Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 30 12:30:45 volumio volumio[856]: info: Received Get System Info Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 30 12:30:45 volumio volumio[856]: info: Discovery: Getting this device information Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: Listing playlists Apr 30 12:30:45 volumio volumio[856]: info: Received Get System Info Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 30 12:30:45 volumio volumio[856]: info: Discovery: Getting this device information Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 30 12:30:45 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:30:46 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 30 12:30:49 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 30 12:30:52 volumio volumio[856]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/download/touch_display/3.5.1/volumio/buster/armhf Apr 30 12:30:53 volumio go-librespot[1083]: time="2025-04-30T12:30:53+01:00" level=debug msg="fetched chunk 5/12, size: 524288" uri="spotify:track:5iXnD2VizcAbErpkcuNQ6I" Apr 30 12:30:53 volumio volumio[856]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/download/touch_display/3.5.1/volumio/buster/armhf Apr 30 12:30:53 volumio volumio[856]: info: Folder /tmp/plugins removed Apr 30 12:30:54 volumio volumio[856]: info: Check plugin dependencies Apr 30 12:30:54 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 30 12:30:54 volumio volumio[856]: info: Checking if plugin already exists Apr 30 12:30:54 volumio volumio[856]: info: Rename folder Apr 30 12:30:54 volumio volumio[856]: info: Folder /tmp/downloaded_plugin.zip removed Apr 30 12:30:54 volumio volumio[856]: info: Move to category Apr 30 12:30:56 volumio volumio[856]: info: Checking if install.sh is present Apr 30 12:30:56 volumio volumio[856]: info: Executing install.sh Apr 30 12:30:56 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 30 12:30:56 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 30 12:30:56 volumio sudo[4508]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/user_interface/touch_display/install.sh Apr 30 12:30:56 volumio sudo[4508]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 30 12:30:56 volumio volumio[856]: info: Re-synchronizing package index files from their sources Apr 30 12:30:57 volumio volumio[856]: info: Hit:1 https://deb.nodesource.com/node_14.x buster InRelease Apr 30 12:30:57 volumio volumio[856]: info: Hit:2 http://archive.raspberrypi.org/debian buster InRelease Apr 30 12:30:57 volumio volumio[856]: info: Hit:3 http://raspbian.raspberrypi.org/raspbian buster InRelease Apr 30 12:31:00 volumio volumio[856]: info: Reading package lists... Apr 30 12:31:00 volumio volumio[856]: info: Running apt-get -y install failed Apr 30 12:31:00 volumio volumio[856]: info: Plugin failed to install! Apr 30 12:31:00 volumio volumio[856]: info: Cleaning up... Apr 30 12:31:02 volumio systemd[1]: Reloading. Apr 30 12:31:02 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Apr 30 12:31:02 volumio volumio[856]: info: Removing dependencies Apr 30 12:31:02 volumio volumio[856]: info: Deleting /opt/volumiokiosk.sh Apr 30 12:31:02 volumio volumio[856]: info: Deleting /data/volumiokiosk Apr 30 12:31:02 volumio volumio[856]: info: Deleting /data/volumiokioskextensions Apr 30 12:31:02 volumio volumio[856]: info: Deleting /lib/systemd/system/volumio-kiosk.service Apr 30 12:31:02 volumio volumio[856]: info: Enabling login prompt Apr 30 12:31:02 volumio volumio[856]: info: Done Apr 30 12:31:02 volumio volumio[856]: info: Removing plugin directory /data/plugins/user_interface/touch_display Apr 30 12:31:03 volumio go-librespot[1083]: time="2025-04-30T12:31:03+01:00" level=trace msg="sent dealer ping" Apr 30 12:31:03 volumio go-librespot[1083]: time="2025-04-30T12:31:03+01:00" level=trace msg="received dealer pong" Apr 30 12:31:05 volumio go-librespot[1083]: time="2025-04-30T12:31:05+01:00" level=debug msg="fetched chunk 6/12, size: 524288" uri="spotify:track:5iXnD2VizcAbErpkcuNQ6I" Apr 30 12:31:07 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 30 12:31:08 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 30 12:31:08 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 30 12:31:08 volumio volumio[856]: info: Discovery: Getting this device information Apr 30 12:31:08 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 30 12:31:08 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 30 12:31:09 volumio volumio[856]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/download/touch_display/3.5.1/volumio/buster/armhf Apr 30 12:31:10 volumio volumio[856]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/download/touch_display/3.5.1/volumio/buster/armhf Apr 30 12:31:10 volumio volumio[856]: info: Folder /tmp/plugins removed Apr 30 12:31:13 volumio volumio[856]: info: Removing temporary directory /tmp/touch_display-Ef87SrbkKf Apr 30 12:31:13 volumio sudo[4508]: pam_unix(sudo:session): session closed for user root Apr 30 12:31:13 volumio volumio[856]: info: Install script return the error Error: Command failed: echo volumio | sudo -S sh /data/plugins/user_interface/touch_display/install.sh > /tmp/installog Apr 30 12:31:13 volumio volumio[856]: [sudo] password for volumio: E: dpkg was interrupted, you must manually run 'sudo dpkg --configure -a' to correct the problem. Apr 30 12:31:13 volumio volumio[856]: E: dpkg was interrupted, you must manually run 'sudo dpkg --configure -a' to correct the problem. Apr 30 12:31:13 volumio volumio[856]: rm: cannot remove '/opt/volumiokiosk.sh': No such file or directory Apr 30 12:31:13 volumio volumio[856]: rm: cannot remove '/lib/systemd/system/volumio-kiosk.service': No such file or directory Apr 30 12:31:13 volumio volumio[856]: info: An error occurred installing the plugin. Rolling back config Apr 30 12:31:13 volumio volumio[856]: info: Plugin folders cleanup Apr 30 12:31:13 volumio volumio[856]: info: Scanning into folder /volumio/app/plugins/ Apr 30 12:31:13 volumio volumio[856]: info: Scanning category audio_interface Apr 30 12:31:13 volumio volumio[856]: info: Scanning category miscellanea Apr 30 12:31:13 volumio volumio[856]: info: Scanning category music_service Apr 30 12:31:13 volumio volumio[856]: info: Scanning category plugins.json Apr 30 12:31:13 volumio volumio[856]: info: Scanning category system_controller Apr 30 12:31:13 volumio volumio[856]: info: Scanning category user_interface Apr 30 12:31:13 volumio volumio[856]: info: Scanning into folder /data/plugins/ Apr 30 12:31:13 volumio volumio[856]: info: Scanning category music_service Apr 30 12:31:13 volumio volumio[856]: info: Scanning category user_interface Apr 30 12:31:13 volumio volumio[856]: info: Plugin folders cleanup completed Apr 30 12:31:13 volumio volumio[856]: info: Error: Error Apr 30 12:31:13 volumio volumio[856]: Plugin install end detected on script Apr 30 12:31:13 volumio volumio[856]: info: Folder /tmp/plugins removed Apr 30 12:31:13 volumio volumio[856]: info: Folder /tmp/downloaded_plugin.zip removed Apr 30 12:31:13 volumio volumio[856]: info: Folder /data/temp removed Apr 30 12:31:13 volumio volumio[856]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 30 12:31:13 volumio volumio[856]: Error: Unable to resolve or reject the same promise twice Apr 30 12:31:13 volumio volumio[856]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Apr 30 12:31:13 volumio volumio[856]: at /volumio/app/pluginmanager.js:1087:11 Apr 30 12:31:13 volumio volumio[856]: at CB (/volumio/node_modules/fs-extra/lib/remove/rimraf.js:57:5) Apr 30 12:31:13 volumio volumio[856]: at /volumio/node_modules/fs-extra/lib/remove/rimraf.js:213:24 Apr 30 12:31:13 volumio volumio[856]: at CB (/volumio/node_modules/fs-extra/lib/remove/rimraf.js:57:5) Apr 30 12:31:13 volumio volumio[856]: at /volumio/node_modules/fs-extra/lib/remove/rimraf.js:213:24 Apr 30 12:31:13 volumio volumio[856]: at CB (/volumio/node_modules/fs-extra/lib/remove/rimraf.js:57:5) Apr 30 12:31:13 volumio volumio[856]: at FSReqCallback.oncomplete (fs.js:171:23) Apr 30 12:31:13 volumio volumio[856]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 30 12:31:13 volumio sudo[4812]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-30 12:30 Apr 30 12:31:13 volumio sudo[4812]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 24 Apr 2025 09:33:57 AM CEST" VOLUMIO_VERSION="3.804" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="354f95cf0a6c2cbcd57b1aca3179c81c"