-- Logs begin at Mon 2024-08-05 04:40:31 UTC, end at Sun 2024-08-18 16:22:04 UTC. -- Aug 18 16:21:16 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 18 16:21:16 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 18 16:21:16 volumio volumio[744]: info: Discovery: Getting this device information Aug 18 16:21:16 volumio volumio[744]: info: CoreCommandRouter::volumioGetState Aug 18 16:21:16 volumio volumio[744]: info: CorePlayQueue::getTrack 5 Aug 18 16:21:16 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 18 16:21:17 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 18 16:21:23 volumio volumio[744]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/download/spop/4.0.2/volumio/buster/armhf Aug 18 16:21:26 volumio volumio[744]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/download/spop/4.0.2/volumio/buster/armhf Aug 18 16:21:26 volumio volumio[744]: info: Folder /tmp/plugins removed Aug 18 16:21:29 volumio volumio[744]: info: Check plugin dependencies Aug 18 16:21:29 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 18 16:21:29 volumio volumio[744]: info: Checking if plugin already exists Aug 18 16:21:29 volumio volumio[744]: info: Rename folder Aug 18 16:21:29 volumio volumio[744]: info: Folder /tmp/downloaded_plugin.zip removed Aug 18 16:21:29 volumio volumio[744]: info: Move to category Aug 18 16:21:31 volumio volumio[744]: info: Checking if install.sh is present Aug 18 16:21:31 volumio volumio[744]: info: Executing install.sh Aug 18 16:21:32 volumio sudo[6733]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/music_service/spop/install.sh Aug 18 16:21:32 volumio sudo[6733]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 16:21:32 volumio volumio[744]: info: Installing Go-librespot Aug 18 16:21:32 volumio volumio[744]: info: Checking old vollibrespot installs Aug 18 16:21:32 volumio systemd[1]: Reloading. Aug 18 16:21:33 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. Aug 18 16:21:34 volumio systemd[1]: Reloading. Aug 18 16:21:35 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. Aug 18 16:21:36 volumio volumio[744]: info: Dowloading daemon Aug 18 16:21:40 volumio volumio[744]: info: Creating Start Script Aug 18 16:21:40 volumio systemd[1]: Reloading. Aug 18 16:21:41 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. Aug 18 16:21:42 volumio sudo[6733]: pam_unix(sudo:session): session closed for user root Aug 18 16:21:42 volumio volumio[744]: Plugin install end detected on script Aug 18 16:21:42 volumio volumio[744]: info: Install script completed Aug 18 16:21:42 volumio volumio[744]: info: Adding reference to registry Aug 18 16:21:42 volumio volumio[744]: info: Done installing plugin. Aug 18 16:21:42 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 18 16:21:42 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 18 16:21:42 volumio volumio[744]: info: Folder /tmp/plugins removed Aug 18 16:21:42 volumio volumio[744]: info: Folder /tmp/downloaded_plugin.zip removed Aug 18 16:21:42 volumio volumio[744]: info: Folder /data/temp removed Aug 18 16:21:46 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 18 16:21:46 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 18 16:21:46 volumio volumio[744]: info: Discovery: Getting this device information Aug 18 16:21:46 volumio volumio[744]: info: CoreCommandRouter::volumioGetState Aug 18 16:21:46 volumio volumio[744]: info: CorePlayQueue::getTrack 5 Aug 18 16:21:46 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 18 16:21:47 volumio volumio[744]: info: Enabling plugin spop Aug 18 16:21:47 volumio volumio[744]: info: Loading plugin "spop"... Aug 18 16:21:47 volumio volumio[744]: info: PLUGIN START: spop Aug 18 16:21:47 volumio volumio[744]: info: Checking for old spotify connect plugin installed Aug 18 16:21:47 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 18 16:21:47 volumio volumio[744]: [SpotifyConnect] Creating VLS config file Aug 18 16:21:47 volumio volumio[744]: error: Failed to read template file: Error: ENOENT: no such file or directory, open '/data/plugins/music_service/spop/volspotify.tmpl' Aug 18 16:21:47 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 16:21:47 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 16:21:47 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 16:21:47 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 16:21:47 volumio volumio[744]: [SpotifyConnect] Starting metadata listener Aug 18 16:21:47 volumio volumio[744]: [SpotifyConnect] Error: bind EADDRINUSE 0.0.0.0:5030 Aug 18 16:21:47 volumio volumio[744]: at dgram.js:337:20 Aug 18 16:21:47 volumio volumio[744]: at processTicksAndRejections (internal/process/task_queues.js:81:21) Aug 18 16:21:47 volumio volumio[744]: (node:744) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'replace' of undefined Aug 18 16:21:47 volumio volumio[744]: at ControllerSpotify.createConfigFile (/data/plugins/music_service/spop/index.js:2578:27) Aug 18 16:21:47 volumio volumio[744]: at ControllerSpotify.init (/data/plugins/music_service/spop/index.js:2441:14) Aug 18 16:21:47 volumio volumio[744]: at Promise._successFn (/data/plugins/music_service/spop/index.js:133:14) Aug 18 16:21:47 volumio volumio[744]: at nextTickCallback (/data/plugins/music_service/spop/node_modules/kew/kew.js:47:28) Aug 18 16:21:47 volumio volumio[744]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Aug 18 16:21:47 volumio volumio[744]: (node:744) 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) Aug 18 16:21:47 volumio volumio[744]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Aug 18 16:21:47 volumio sudo[6793]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volspotconnect.service Aug 18 16:21:47 volumio sudo[6793]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 16:21:47 volumio systemd[1]: Started Volspotconnect2 Daemon. Aug 18 16:21:47 volumio sudo[6793]: pam_unix(sudo:session): session closed for user root Aug 18 16:21:47 volumio volumio[6795]: /usr/lib/startconnect.sh: line 2: ./usr/bin/vollibrespot: No such file or directory Aug 18 16:21:47 volumio volumio[744]: [SpotifyConnect] Vollibrespot Daemon service started! Aug 18 16:21:47 volumio volumio[744]: [Metrics] SpotifyConnect: 0s 251.00ms Aug 18 16:21:47 volumio volumio[744]: info: Done. Aug 18 16:21:47 volumio systemd[1]: volspotconnect.service: Main process exited, code=exited, status=127/n/a Aug 18 16:21:47 volumio systemd[1]: volspotconnect.service: Failed with result 'exit-code'. Aug 18 16:21:49 volumio systemd[1]: volspotconnect.service: Service RestartSec=2s expired, scheduling restart. Aug 18 16:21:49 volumio systemd[1]: volspotconnect.service: Scheduled restart job, restart counter is at 1. Aug 18 16:21:49 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Aug 18 16:21:49 volumio systemd[1]: Started Volspotconnect2 Daemon. Aug 18 16:21:49 volumio volumio[6797]: /usr/lib/startconnect.sh: line 2: ./usr/bin/vollibrespot: No such file or directory Aug 18 16:21:49 volumio systemd[1]: volspotconnect.service: Main process exited, code=exited, status=127/n/a Aug 18 16:21:49 volumio systemd[1]: volspotconnect.service: Failed with result 'exit-code'. Aug 18 16:21:51 volumio volumio[744]: info: Checking Spotify Web API Aug 18 16:21:52 volumio systemd[1]: volspotconnect.service: Service RestartSec=2s expired, scheduling restart. Aug 18 16:21:52 volumio systemd[1]: volspotconnect.service: Scheduled restart job, restart counter is at 2. Aug 18 16:21:52 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Aug 18 16:21:52 volumio systemd[1]: Started Volspotconnect2 Daemon. Aug 18 16:21:52 volumio volumio[6799]: /usr/lib/startconnect.sh: line 2: ./usr/bin/vollibrespot: No such file or directory Aug 18 16:21:52 volumio systemd[1]: volspotconnect.service: Main process exited, code=exited, status=127/n/a Aug 18 16:21:52 volumio systemd[1]: volspotconnect.service: Failed with result 'exit-code'. Aug 18 16:21:52 volumio volumio[744]: info: Enabling plugin spop Aug 18 16:21:52 volumio volumio[744]: info: Loading plugin "spop"... Aug 18 16:21:52 volumio volumio[744]: info: PLUGIN START: spop Aug 18 16:21:52 volumio volumio[744]: info: Checking for old spotify connect plugin installed Aug 18 16:21:53 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Aug 18 16:21:53 volumio volumio[744]: [SpotifyConnect] Creating VLS config file Aug 18 16:21:53 volumio volumio[744]: error: Failed to read template file: Error: ENOENT: no such file or directory, open '/data/plugins/music_service/spop/volspotify.tmpl' Aug 18 16:21:53 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 16:21:53 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 16:21:53 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 16:21:53 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 16:21:53 volumio volumio[744]: [SpotifyConnect] Starting metadata listener Aug 18 16:21:53 volumio volumio[744]: [SpotifyConnect] Error: bind EADDRINUSE 0.0.0.0:5030 Aug 18 16:21:53 volumio volumio[744]: at dgram.js:337:20 Aug 18 16:21:53 volumio volumio[744]: at processTicksAndRejections (internal/process/task_queues.js:81:21) Aug 18 16:21:53 volumio volumio[744]: (node:744) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'replace' of undefined Aug 18 16:21:53 volumio volumio[744]: at ControllerSpotify.createConfigFile (/data/plugins/music_service/spop/index.js:2578:27) Aug 18 16:21:53 volumio volumio[744]: at ControllerSpotify.init (/data/plugins/music_service/spop/index.js:2441:14) Aug 18 16:21:53 volumio volumio[744]: at Promise._successFn (/data/plugins/music_service/spop/index.js:133:14) Aug 18 16:21:53 volumio volumio[744]: at nextTickCallback (/data/plugins/music_service/spop/node_modules/kew/kew.js:47:28) Aug 18 16:21:53 volumio volumio[744]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Aug 18 16:21:53 volumio volumio[744]: (node:744) 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: 10) Aug 18 16:21:54 volumio systemd[1]: volspotconnect.service: Service RestartSec=2s expired, scheduling restart. Aug 18 16:21:54 volumio systemd[1]: volspotconnect.service: Scheduled restart job, restart counter is at 3. Aug 18 16:21:54 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Aug 18 16:21:54 volumio systemd[1]: Started Volspotconnect2 Daemon. Aug 18 16:21:54 volumio volumio[744]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Aug 18 16:21:54 volumio volumio[6804]: /usr/lib/startconnect.sh: line 2: ./usr/bin/vollibrespot: No such file or directory Aug 18 16:21:54 volumio systemd[1]: volspotconnect.service: Main process exited, code=exited, status=127/n/a Aug 18 16:21:54 volumio sudo[6803]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volspotconnect.service Aug 18 16:21:54 volumio systemd[1]: volspotconnect.service: Failed with result 'exit-code'. Aug 18 16:21:54 volumio sudo[6803]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 16:21:56 volumio systemd[1]: volspotconnect.service: Service RestartSec=2s expired, scheduling restart. Aug 18 16:21:56 volumio systemd[1]: volspotconnect.service: Scheduled restart job, restart counter is at 4. Aug 18 16:21:56 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Aug 18 16:21:56 volumio systemd[1]: Started Volspotconnect2 Daemon. Aug 18 16:21:56 volumio sudo[6803]: pam_unix(sudo:session): session closed for user root Aug 18 16:21:56 volumio volumio[744]: [SpotifyConnect] Vollibrespot Daemon service started! Aug 18 16:21:56 volumio volumio[744]: [Metrics] SpotifyConnect: 3s 656.71ms Aug 18 16:21:56 volumio volumio[744]: info: Done. Aug 18 16:21:56 volumio volumio[6807]: /usr/lib/startconnect.sh: line 2: ./usr/bin/vollibrespot: No such file or directory Aug 18 16:21:56 volumio systemd[1]: volspotconnect.service: Main process exited, code=exited, status=127/n/a Aug 18 16:21:56 volumio systemd[1]: volspotconnect.service: Failed with result 'exit-code'. Aug 18 16:21:58 volumio volumio[744]: info: CorePlayQueue::getTrack 5 Aug 18 16:21:58 volumio volumio[744]: info: CorePlayQueue::getTrack 6 Aug 18 16:21:58 volumio volumio[744]: info: Prefetching next song Aug 18 16:21:58 volumio volumio[744]: info: DOING PREFETCH IN MPD Aug 18 16:21:58 volumio volumio[744]: verbose: ControllerMpd::sendMpdCommand add "USB/PHILIPS_UFD/Muziek/CD HANS/07 - Chris Rea - Summer Love.mp3" Aug 18 16:21:58 volumio volumio[744]: info: Aug 18 16:21:58 volumio volumio[744]: ---------------------------- MPD announces system playlist update Aug 18 16:21:58 volumio volumio[744]: info: Ignoring MPD Status Update Aug 18 16:21:58 volumio volumio[744]: info: sendMpdCommand add "USB/PHILIPS_UFD/Muziek/CD HANS/07 - Chris Rea - Summer Love.mp3" took 5 milliseconds Aug 18 16:21:58 volumio volumio[744]: verbose: ControllerMpd::sendMpdCommand consume 1 Aug 18 16:21:58 volumio volumio[744]: info: ------------------------------ 7ms Aug 18 16:21:58 volumio volumio[744]: info: sendMpdCommand consume 1 took 4 milliseconds Aug 18 16:21:58 volumio systemd[1]: volspotconnect.service: Service RestartSec=2s expired, scheduling restart. Aug 18 16:21:58 volumio systemd[1]: volspotconnect.service: Scheduled restart job, restart counter is at 5. Aug 18 16:21:58 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Aug 18 16:21:58 volumio systemd[1]: Started Volspotconnect2 Daemon. Aug 18 16:21:58 volumio volumio[6809]: /usr/lib/startconnect.sh: line 2: ./usr/bin/vollibrespot: No such file or directory Aug 18 16:21:58 volumio systemd[1]: volspotconnect.service: Main process exited, code=exited, status=127/n/a Aug 18 16:21:58 volumio systemd[1]: volspotconnect.service: Failed with result 'exit-code'. Aug 18 16:22:00 volumio volumio[744]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Aug 18 16:22:00 volumio volumio[744]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 18 16:22:00 volumio volumio[744]: [SpotifyConnect] Closing metadata listener Aug 18 16:22:00 volumio volumio[744]: info: Disabling plugin spop Aug 18 16:22:00 volumio volumio[744]: info: Done. Aug 18 16:22:00 volumio sudo[6812]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volspotconnect.service Aug 18 16:22:00 volumio sudo[6812]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 16:22:00 volumio systemd[1]: Stopped Volspotconnect2 Daemon. Aug 18 16:22:00 volumio sudo[6812]: pam_unix(sudo:session): session closed for user root Aug 18 16:22:00 volumio volumio[744]: [SpotifyConnect] Vollibrespot Daemon service stoped! Aug 18 16:22:00 volumio volumio[744]: info: Checking Spotify Web API Aug 18 16:22:00 volumio volumio[744]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 18 16:22:00 volumio volumio[744]: Error [ERR_SOCKET_DGRAM_NOT_RUNNING]: Not running Aug 18 16:22:00 volumio volumio[744]: at healthCheck (dgram.js:897:11) Aug 18 16:22:00 volumio volumio[744]: at Socket.send (dgram.js:622:3) Aug 18 16:22:00 volumio volumio[744]: at SpotConnEvents.sendmsg (/data/plugins/music_service/spop/SpotConnController.js:106:21) Aug 18 16:22:00 volumio volumio[744]: at ControllerSpotify.checkWebApi (/data/plugins/music_service/spop/index.js:2354:23) Aug 18 16:22:00 volumio volumio[744]: at Timeout._onTimeout (/data/plugins/music_service/spop/index.js:2446:18) Aug 18 16:22:00 volumio volumio[744]: at listOnTimeout (internal/timers.js:554:17) Aug 18 16:22:00 volumio volumio[744]: at processTimers (internal/timers.js:497:7) { Aug 18 16:22:00 volumio volumio[744]: code: 'ERR_SOCKET_DGRAM_NOT_RUNNING' Aug 18 16:22:00 volumio volumio[744]: } Aug 18 16:22:00 volumio volumio[744]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 18 16:22:04 volumio sudo[6823]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-18 16:21 Aug 18 16:22:04 volumio sudo[6823]: 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="1c5fa5a8788b087ca429be9d10851b25c5cc4f5b" VOLUMIO_FE_VERSION="e5ce74e254a237ac98580c4437c4ed223c7d5cd9" VOLUMIO_FE3_VERSION="a86adf3c7ed2d6c50d9bca768f58ab2f56832dc1" VOLUMIO_BE_VERSION="c8882d89d3d4e0a1571e0dc9701741128f5a1656" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 31 Mar 2022 02:51:41 PM CEST" VOLUMIO_VERSION="3.251" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e83cc5fcd68eb3ee4105ab0b8b3779ea"