Oct 25 09:50:14 volumio ntpd[939]: CLOCK: time stepped by 32.639428 Oct 25 09:50:14 volumio ntpd[939]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Oct 25 09:50:14 volumio volumio[1282]: info: Loading plugin "alarm-clock"... Oct 25 09:50:14 volumio volumio[1282]: info: Loading plugin "airplay_emulation"... Oct 25 09:50:14 volumio volumio[1282]: info: Starting Shairport Sync Oct 25 09:50:14 volumio volumio[1282]: info: Loading plugin "last_100"... Oct 25 09:50:14 volumio volumio[1282]: info: Loading plugin "webradio"... Oct 25 09:50:15 volumio volumio[1282]: info: Loading plugin "i2s_dacs"... Oct 25 09:50:15 volumio volumio[1282]: info: Loading plugin "volumiodiscovery"... Oct 25 09:50:15 volumio volumio[1282]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 25 09:50:15 volumio node[1282]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 25 09:50:15 volumio volumio[1282]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 25 09:50:15 volumio node[1282]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 25 09:50:15 volumio volumio[1282]: *** WARNING *** For more information see Oct 25 09:50:15 volumio node[1282]: *** WARNING *** For more information see Oct 25 09:50:15 volumio volumio[1282]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 25 09:50:15 volumio node[1282]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 25 09:50:15 volumio volumio[1282]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 25 09:50:15 volumio node[1282]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 25 09:50:15 volumio volumio[1282]: *** WARNING *** For more information see Oct 25 09:50:15 volumio node[1282]: *** WARNING *** For more information see Oct 25 09:50:15 volumio volumio[1282]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 25 09:50:15 volumio volumio[1282]: info: Discovery: Started advertising with name: Volumio Oct 25 09:50:15 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 25 09:50:15 volumio volumio[1282]: info: Loading plugin "spop"... Oct 25 09:50:16 volumio volumio[1282]: info: Loading plugin "youtube2"... Oct 25 09:50:16 volumio sudo[1344]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:16 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully. Oct 25 09:50:18 volumio dhcpcd[617]: timed out Oct 25 09:50:18 volumio sh[606]: timed out Oct 25 09:50:18 volumio sh[553]: ifup: failed to bring up eth0 Oct 25 09:50:18 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Oct 25 09:50:18 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Oct 25 09:50:19 volumio volumio[1282]: info: Loading plugin "ytcr"... Oct 25 09:50:20 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Oct 25 09:50:22 volumio volumio[1282]: info: Loading plugin "ytmusic"... Oct 25 09:50:25 volumio volumio[1282]: info: Loading plugin "outputs"... Oct 25 09:50:25 volumio volumio[1282]: info: Loading plugin "albumart"... Oct 25 09:50:25 volumio volumio[1282]: info: Plugin example_plugin is not enabled Oct 25 09:50:25 volumio volumio[1282]: info: Loading plugin "inputs"... Oct 25 09:50:25 volumio volumio[1282]: info: Loading plugin "updater_comm"... Oct 25 09:50:25 volumio volumio[1282]: info: Plugin mpdemulation is not enabled Oct 25 09:50:25 volumio volumio[1282]: info: Loading plugin "rest_api"... Oct 25 09:50:25 volumio volumio[1282]: info: Loading plugin "websocket"... Oct 25 09:50:25 volumio volumio[1282]: info: Starting Socket.io Server version 1.7.4 Oct 25 09:50:25 volumio volumio[1282]: info: Loading plugin "peppyspectrum"... Oct 25 09:50:25 volumio volumio[1402]: Forking 3 albumart workers Oct 25 09:50:26 volumio volumio[1282]: info: Loading plugin "touch_display"... Oct 25 09:50:26 volumio volumio-remote-updater[710]: [2025-10-25 09:50:26] [connect] Successful connection Oct 25 09:50:27 volumio volumio[1282]: info: Applying required configuration parameters for plugin touch_display Oct 25 09:50:27 volumio volumio[1282]: info: Loading i18n strings for locale de Oct 25 09:50:27 volumio volumio[1282]: Updating browse sources language Oct 25 09:50:27 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 09:50:28 volumio volumio[1413]: Starting albumart workers Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::initPlayerControls Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 25 09:50:28 volumio volumio[1282]: Express server listening on port 3000 Oct 25 09:50:28 volumio volumio[1282]: [Metrics] WebUI: 18s 770.07ms Oct 25 09:50:28 volumio volumio[1282]: info: CoreStateMachine::resetVolumioState Oct 25 09:50:28 volumio volumio[1282]: info: CoreStateMachine::getcurrentVolume Oct 25 09:50:28 volumio volumio[1282]: info: CoreCommandRouter::volumioRetrievevolume Oct 25 09:50:28 volumio sudo[1449]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 25 09:50:29 volumio sudo[1447]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 25 09:50:29 volumio sudo[1447]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:29 volumio volumio[1414]: Starting albumart workers Oct 25 09:50:29 volumio sudo[1449]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:29 volumio sudo[1447]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:29 volumio sudo[1449]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:29 volumio volumio[1282]: info: Volumio Network Manager: Network status updated: 2 Oct 25 09:50:29 volumio volumio[1412]: Starting albumart workers Oct 25 09:50:29 volumio volumio[1282]: verbose: New Socket.io Connection to 192.168.178.74 from 192.168.178.113 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7 Pro Build/BP3A.251005.004.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.97 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Oct 25 09:50:29 volumio volumio[1282]: info: VolumeController:: Volume=66 Mute =false Oct 25 09:50:29 volumio volumio[1282]: info: CoreStateMachine::pushState Oct 25 09:50:29 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 09:50:29 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:50:29 volumio volumio[1282]: info: CoreStateMachine::updateTrackBlock Oct 25 09:50:29 volumio volumio[1282]: info: CorePlayQueue::getTrackBlock Oct 25 09:50:29 volumio volumio[1282]: info: CoreCommandRouter::volumioRetrievevolume Oct 25 09:50:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:29 volumio volumio[1282]: info: Reloading queue from file Oct 25 09:50:29 volumio volumio[1282]: info: CoreStateMachine::setRepeat false single undefined Oct 25 09:50:29 volumio volumio[1282]: info: CoreStateMachine::pushState Oct 25 09:50:29 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 09:50:29 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:50:29 volumio volumio[1282]: info: CoreStateMachine::setRandom true Oct 25 09:50:29 volumio volumio[1282]: info: CoreStateMachine::pushState Oct 25 09:50:29 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 09:50:29 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:50:29 volumio volumio[1282]: info: Setting Device type: Raspberry PI Oct 25 09:50:29 volumio volumio[1282]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 25 09:50:29 volumio volumio[1282]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Oct 25 09:50:29 volumio volumio[1282]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 25 09:50:29 volumio volumio[1282]: verbose: New Socket.io Connection to 192.168.178.74 from 192.168.178.113 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7 Pro Build/BP3A.251005.004.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.97 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Oct 25 09:50:29 volumio volumio[1282]: info: Completed loading Core Plugins Oct 25 09:50:29 volumio volumio[1282]: info: Preparing to generate the ALSA configuration file Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 25 09:50:30 volumio volumio[1282]: info: Discovery: Getting this device information Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:50:30 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 25 09:50:30 volumio volumio[1282]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Oct 25 09:50:30 volumio volumio[1282]: info: Reading ALSA contributions from plugins. Oct 25 09:50:30 volumio volumio[1282]: verbose: New Socket.io Connection to 192.168.178.74 from 192.168.178.113 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7 Pro Build/BP3A.251005.004.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.97 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Oct 25 09:50:30 volumio volumio[1282]: verbose: New Socket.io Connection to 192.168.178.74:3000 from 192.168.178.113 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Oct 25 09:50:30 volumio volumio[1282]: info: VolumeController:: Volume=66 Mute =false Oct 25 09:50:30 volumio volumio[1282]: info: CoreStateMachine::pushState Oct 25 09:50:30 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:50:30 volumio sudo[1477]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 25 09:50:30 volumio sudo[1477]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:30 volumio volumio[1282]: info: Discovery: adding ab2f74f2-2547-4a63-a014-36eb0d487233 Oct 25 09:50:30 volumio volumio[1282]: info: Discovery: Found device Volumio Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:50:30 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:30 volumio volumio-remote-updater[710]: [2025-10-25 09:50:30] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761378626 101 Oct 25 09:50:30 volumio volumio[1282]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 5 Oct 25 09:50:30 volumio volumio[1282]: verbose: New Socket.io Connection to 192.168.178.74 from 192.168.178.113 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7 Pro Build/BP3A.251005.004.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.97 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Oct 25 09:50:30 volumio volumio[1282]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 25 09:50:30 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 25 09:50:30 volumio volumio[1282]: info: Discovery: this is already registered, ab2f74f2-2547-4a63-a014-36eb0d487233 Oct 25 09:50:30 volumio volumio[1282]: info: Discovery: Found device Volumio Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:50:30 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:30 volumio sudo[1477]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:30 volumio volumio[1282]: info: Upmpdcli Daemon Started Oct 25 09:50:30 volumio volumio[1282]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 Oct 25 09:50:30 volumio volumio[1282]: info: Asound.conf file unchanged, so no further update is needed Oct 25 09:50:30 volumio volumio[1282]: info: Output device has changed, restarting MPD Oct 25 09:50:30 volumio sudo[1492]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 25 09:50:30 volumio volumio[1282]: info: Output device has changed, restarting Shairport Sync Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:30 volumio sudo[1492]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:30 volumio sudo[1492]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:30 volumio sudo[1494]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 25 09:50:30 volumio volumio[1282]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 25 09:50:30 volumio sudo[1494]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:30 volumio volumio[1282]: info: ___________ START PLUGINS ___________ Oct 25 09:50:30 volumio volumio[1282]: info: ControllerMpd::onStart: Initializing MPD Oct 25 09:50:30 volumio volumio[1282]: info: Creating MPD Configuration file Oct 25 09:50:30 volumio sudo[1502]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 25 09:50:30 volumio sudo[1502]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:30 volumio sudo[1502]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:30 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 09:50:30 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 25 09:50:30 volumio volumio[1282]: info: [1761378630791] CoreMusicLibrary::Adding element Medienserver Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 09:50:30 volumio sudo[1506]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 25 09:50:30 volumio sudo[1506]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:30 volumio sudo[1507]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 25 09:50:30 volumio sudo[1507]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 25 09:50:30 volumio sudo[1507]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:30 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 25 09:50:30 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 25 09:50:30 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 25 09:50:30 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 25 09:50:30 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 25 09:50:30 volumio volumio[1282]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:30 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:30 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 25 09:50:30 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 25 09:50:31 volumio volumio[1282]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 25 09:50:31 volumio volumio[1282]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 09:50:31 volumio volumio[1282]: info: [1761378631049] CoreMusicLibrary::Adding element Last_100 Oct 25 09:50:31 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 09:50:31 volumio volumio[1282]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 09:50:31 volumio volumio[1282]: info: [1761378631051] CoreMusicLibrary::Adding element Webradio Oct 25 09:50:31 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 09:50:31 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 25 09:50:31 volumio volumio[1282]: info: Initializing BBC Radios Oct 25 09:50:31 volumio sudo[1521]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 25 09:50:31 volumio sudo[1521]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 25 09:50:31 volumio sudo[1525]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 25 09:50:31 volumio sudo[1521]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:31 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 25 09:50:31 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 25 09:50:31 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:31 volumio volumio[1282]: info: Creating Spotify config file Oct 25 09:50:31 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:32 volumio volumio[1282]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 09:50:32 volumio volumio[1282]: info: [1761378632440] CoreMusicLibrary::Adding element YouTube2 Oct 25 09:50:32 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 09:50:32 volumio volumio[1282]: Cannot find translation for source YouTube2 Oct 25 09:50:32 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 25 09:50:32 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 25 09:50:32 volumio volumio[1282]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 09:50:32 volumio volumio[1282]: info: [1761378632891] CoreMusicLibrary::Adding element YouTube Music Oct 25 09:50:32 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 09:50:32 volumio volumio[1282]: Cannot find translation for source YouTube2 Oct 25 09:50:32 volumio volumio[1282]: Cannot find translation for source YouTube Music Oct 25 09:50:32 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Oct 25 09:50:33 volumio volumio[1282]: info: Loading i18n strings for locale de Oct 25 09:50:33 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 25 09:50:33 volumio volumio[1282]: info: Volumio Calling Home Oct 25 09:50:33 volumio volumio[1282]: info: Preparing to generate the ALSA configuration file Oct 25 09:50:33 volumio sudo[1585]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Oct 25 09:50:33 volumio sudo[1585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:33 volumio sudo[1583]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Oct 25 09:50:33 volumio sudo[1583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:33 volumio systemd[1]: Reloading. Oct 25 09:50:33 volumio sudo[1588]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Oct 25 09:50:33 volumio sudo[1588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:33 volumio volumio[1282]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Oct 25 09:50:33 volumio volumio[1282]: info: Reading ALSA contributions from plugins. Oct 25 09:50:33 volumio volumio[1282]: info: touch_display: No backlight interface detected. Oct 25 09:50:33 volumio volumio[1282]: info: MPD Permissions set Oct 25 09:50:33 volumio volumio[1282]: info: MPD Permissions set Oct 25 09:50:34 volumio volumio[1282]: info: Volumio called home Oct 25 09:50:34 volumio volumio[1282]: info: Spotify config file written Oct 25 09:50:34 volumio sudo[1612]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 25 09:50:34 volumio sudo[1612]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:34 volumio sudo[1585]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:34 volumio systemd[1]: Reloading. Oct 25 09:50:35 volumio volumio[1282]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:35 volumio volumio[1282]: info: No need to fix Spotify hosts Oct 25 09:50:36 volumio mpd[1528]: decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 25 09:50:36 volumio mpd[1528]: output: No 'audio_output' defined in config file Oct 25 09:50:36 volumio mpd[1528]: output: Successfully detected a sndio audio device Oct 25 09:50:36 volumio mpd[1528]: zeroconf: No global port, disabling zeroconf Oct 25 09:50:36 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 25 09:50:36 volumio sudo[1588]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:36 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:50:36 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:50:36 volumio sudo[1506]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:36 volumio sudo[1494]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:36 volumio volumio[1282]: verbose: New Socket.io Connection to 192.168.178.74 from 192.168.178.113 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7 Pro Build/BP3A.251005.004.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.97 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Oct 25 09:50:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 09:50:36 volumio go-librespot[1643]: go-librespot daemon starting... Oct 25 09:50:36 volumio sudo[1612]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:36 volumio volumio[1282]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Oct 25 09:50:36 volumio sudo[1583]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:36 volumio volumio[1282]: info: touch_display: systemctl disable getty@tty1.service succeeded. Oct 25 09:50:36 volumio volumio[1282]: info: touch_display: systemctl daemon-reload succeeded. Oct 25 09:50:36 volumio go-librespot[1644]: time="2025-10-25T09:50:36+02:00" level=info msg="running go-librespot 0.4.0" Oct 25 09:50:36 volumio go-librespot[1644]: time="2025-10-25T09:50:36+02:00" level=debug msg="app state loaded" Oct 25 09:50:36 volumio go-librespot[1644]: time="2025-10-25T09:50:36+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 09:50:36 volumio sudo[1653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Oct 25 09:50:36 volumio sudo[1653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:36 volumio volumio[1282]: info: touch_display: No Raspberry Pi Foundation touch screen detected. Oct 25 09:50:36 volumio sudo[1656]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Oct 25 09:50:36 volumio sudo[1656]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:36 volumio sudo[1656]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:36 volumio volumio[1282]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 25 09:50:36 volumio volumio[1282]: SPOTIFY: BQBltGIEmqQUSs4JWrGLz3D8L8wAFjI5pXjnEsAWBzXdzKTyOXlH1J8iKKSpX_5UyqN7FTjtn29vOjkTEeJYDl7p421SkyENwcEbfddNz8DQHiXZwGjZYj621UPQHReE5gN8mD0FJ-DT0lATTptQ2pPbLGElT41HvPC-GmI_0eR9hutvlNYjSQnufJy2FyqWyfZsUHal-Gy-Y4PxgQcZ5rdpYJNOua61Ndwx2stMbaYs5itwR5tjTWH_zRoRuh8lBMZbF2zKB1CCaJVfBtSOtSmkgSr6AY_g Oct 25 09:50:36 volumio volumio[1282]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 25 09:50:36 volumio volumio[1282]: info: New Spotify access token = BQBltGIEmqQUSs4JWrGLz3D8L8wAFjI5pXjnEsAWBzXdzKTyOXlH1J8iKKSpX_5UyqN7FTjtn29vOjkTEeJYDl7p421SkyENwcEbfddNz8DQHiXZwGjZYj621UPQHReE5gN8mD0FJ-DT0lATTptQ2pPbLGElT41HvPC-GmI_0eR9hutvlNYjSQnufJy2FyqWyfZsUHal-Gy-Y4PxgQcZ5rdpYJNOua61Ndwx2stMbaYs5itwR5tjTWH_zRoRuh8lBMZbF2zKB1CCaJVfBtSOtSmkgSr6AY_g Oct 25 09:50:36 volumio volumio[1282]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 25 09:50:36 volumio systemd[1]: Started volumio-kiosk.service - Volumio Kiosk. Oct 25 09:50:36 volumio sudo[1653]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:37 volumio startx[1680]: X.Org X Server 1.21.1.7 Oct 25 09:50:37 volumio startx[1680]: X Protocol Version 11, Revision 0 Oct 25 09:50:37 volumio startx[1680]: Current Operating System: Linux volumio 6.12.34-v7l+ #1889 SMP Mon Jun 23 11:08:21 BST 2025 armv7l Oct 25 09:50:37 volumio startx[1680]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 cgroup_disable=memory numa_policy=interleave nvme.max_host_mem_size_mb=0 snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=1480 bcm2708_fb.fbheight=320 bcm2708_fb.fbswap=1 numa=fake=2 system_heap.max_order=0 smsc95xx.macaddr=DC:A6:32:75:86:B0 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=b5ae27d1-af31-4074-9c18-7c3c8b76887b imgfile=/volumio_current.sqsh bootpart=UUID=DFAD-3773 datapart=UUID=46b4ba52-c06c-44cb-a796-1b092467eff5 uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no cfg80211.ieee80211_regdom=DE Oct 25 09:50:37 volumio startx[1680]: xorg-server 2:21.1.7-3+rpt3+deb12u10 (https://www.debian.org/support) Oct 25 09:50:37 volumio startx[1680]: Current version of pixman: 0.44.0 Oct 25 09:50:37 volumio startx[1680]: Before reporting problems, check http://wiki.x.org Oct 25 09:50:37 volumio startx[1680]: to make sure that you have the latest version. Oct 25 09:50:37 volumio startx[1680]: Markers: (--) probed, (**) from config file, (==) default setting, Oct 25 09:50:37 volumio startx[1680]: (++) from command line, (!!) notice, (II) informational, Oct 25 09:50:37 volumio startx[1680]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Oct 25 09:50:37 volumio startx[1680]: (==) Log file: "/var/log/Xorg.0.log", Time: Sat Oct 25 09:50:37 2025 Oct 25 09:50:37 volumio startx[1680]: (==) Using config directory: "/etc/X11/xorg.conf.d" Oct 25 09:50:37 volumio startx[1680]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Oct 25 09:50:37 volumio volumio[1282]: info: MPD running with PID1528 Oct 25 09:50:37 volumio volumio[1282]: ,establishing connection Oct 25 09:50:37 volumio volumio[1282]: info: touch_display: systemctl stop getty@tty1.service succeeded. Oct 25 09:50:37 volumio volumio[1282]: info: Starting Shairport Sync Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=info msg="zeroconf server listening on port 39985" Oct 25 09:50:37 volumio sudo[1683]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 09:50:37 volumio sudo[1683]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:37 volumio volumio[1282]: info: Starting Shairport Sync Oct 25 09:50:37 volumio sudo[1686]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 09:50:37 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 25 09:50:37 volumio sudo[1686]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:37 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 25 09:50:37 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 09:50:37 volumio systemd[1]: shairport-sync.service: Consumed 1.606s CPU time. Oct 25 09:50:37 volumio volumio[1282]: info: Starting Shairport Sync Oct 25 09:50:37 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 09:50:37 volumio sudo[1683]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:37 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 25 09:50:37 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 25 09:50:37 volumio sudo[1690]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 09:50:37 volumio sudo[1690]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="obtained new client token: AABrXQoy3eNv/WUKSj7r9IAa/77duaGOHFDBgdUswkHfSCnW99TGMtZRyGYd5oVNyVN2vMYDlQ9veke1+YOmNbMP3Ef4a+ieUlZCLpi5yojxuC2hDh90jzslyC5zd9ydxWgXrTVm4s4/LKoxFt/WgAmQiB1LZRZe+sPTdKsVpBSun5L84BLkZ/tX0EikagR/AYWBTWATNzQO3MDeG48CKqpYj6rzU1V4SkffQZ8l647oa2RCM3c6YPI=" Oct 25 09:50:37 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 09:50:37 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 09:50:37 volumio sudo[1686]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:37 volumio volumio[1282]: error: MPD error: The expression evaluated to a falsy value: Oct 25 09:50:37 volumio volumio[1282]: assert.ok(self.idling) Oct 25 09:50:37 volumio volumio[1282]: error: The expression evaluated to a falsy value: Oct 25 09:50:37 volumio volumio[1282]: assert.ok(self.idling) Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 25 09:50:37 volumio volumio[1282]: error: MPD error: The expression evaluated to a falsy value: Oct 25 09:50:37 volumio volumio[1282]: assert.ok(self.idling) Oct 25 09:50:37 volumio volumio[1282]: error: The expression evaluated to a falsy value: Oct 25 09:50:37 volumio volumio[1282]: assert.ok(self.idling) Oct 25 09:50:37 volumio volumio[1282]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Oct 25 09:50:37 volumio volumio[1282]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Oct 25 09:50:37 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="completed keyexchange" Oct 25 09:50:37 volumio volumio[1282]: info: touch_display: Volumio Kiosk started. Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="completed challenge" Oct 25 09:50:37 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 25 09:50:37 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 09:50:37 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:50:37 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=info msg="authenticated AP" username="11*******86" Oct 25 09:50:37 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:50:37 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:37 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 09:50:37 volumio sudo[1690]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:37 volumio volumio[1282]: info: Shairport-Sync Started Oct 25 09:50:37 volumio volumio[1282]: Error adding Membership: Error: addMembership EINVAL Oct 25 09:50:37 volumio volumio[1282]: info: Shairport-Sync Started Oct 25 09:50:37 volumio volumio[1282]: info: Asound.conf file unchanged, so no further update is needed Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=info msg="authenticated Login5" username="11*******86" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="initializing zeroconf session" username="11*******86" Oct 25 09:50:37 volumio volumio[1282]: info: Output device has changed, restarting MPD Oct 25 09:50:37 volumio sudo[1728]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 25 09:50:37 volumio sudo[1728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:37 volumio sudo[1728]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="dealer connection opened" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=trace msg="starting accesspoint recv loop" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=trace msg="starting dealer recv loop" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=trace msg="received accesspoint ping" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="received connection id: ZjM2YjVjZmItODM2...MTVBQTcwMTY0Ng==" Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=trace msg="received accesspoint pong ack" Oct 25 09:50:37 volumio volumio[1282]: info: Output device has changed, restarting Shairport Sync Oct 25 09:50:37 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:37 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:37 volumio sudo[1731]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 25 09:50:37 volumio sudo[1731]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:37 volumio go-librespot[1644]: time="2025-10-25T09:50:37+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 25 09:50:37 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 25 09:50:38 volumio volumio[1282]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 25 09:50:38 volumio volumio[1282]: error: updateQueue error: null Oct 25 09:50:38 volumio volumio[1282]: info: touch_display: X display number found: 0 Oct 25 09:50:38 volumio volumio[1282]: info: Shairport-Sync Started Oct 25 09:50:38 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 25 09:50:38 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 25 09:50:38 volumio systemd[1]: mpd.service: Consumed 3.472s CPU time. Oct 25 09:50:38 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 25 09:50:38 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 25 09:50:38 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 25 09:50:38 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 25 09:50:38 volumio volumio[1282]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Oct 25 09:50:38 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 25 09:50:38 volumio volumio[1282]: info: touch_display: X display number found: 0 Oct 25 09:50:38 volumio volumio[1282]: info: MPD Permissions set Oct 25 09:50:38 volumio sudo[1761]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 25 09:50:38 volumio sudo[1761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 25 09:50:38 volumio sudo[1764]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 25 09:50:38 volumio sudo[1761]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:50:38 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:50:38 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:39 volumio volumio[1282]: info: Starting Shairport Sync Oct 25 09:50:39 volumio sudo[1816]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 09:50:39 volumio sudo[1816]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:39 volumio volumio[1282]: info: touch_display: Setting screensaver timeout to 120 seconds. Oct 25 09:50:39 volumio volumio[1282]: SPOTIFY: User informations: {"country":"DE","display_name":"Chris Müller","email":"chrismuller1996@freenet.de","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/11144377386"},"followers":{"href":null,"total":6},"href":"https://api.spotify.com/v1/users/11144377386","id":"11144377386","images":[{"height":300,"url":"https://scontent-cdg4-3.xx.fbcdn.net/v/t1.6435-1/133114805_3507320386003279_5327632710500324798_n.jpg?stp=c0.0.1343.1343a_dst-jpg_s320x320_tt6&_nc_cat=106&ccb=1-7&_nc_sid=79bf43&_nc_ohc=vC0osGnSDlwQ7kNvwGvrfRZ&_nc_oc=Adks8uj4lip0sJAt5s6hBruJJZS9NOeRJQRalEuVF4M0S0_FWykft9mRfcQWOhtm55nZ3ixQETeV2Hy-fBFf6oaE&_nc_zt=24&_nc_ht=scontent-cdg4-3.xx&edm=AP4hL3IEAAAA&_nc_gid=9Ro4i97lLR-RMwRcyFaE4w&_nc_tpa=Q5bMBQHieujrfx3Smmgv6jkrQFetcO9KKAJJ7oyvitH1LU_rcTc0MHDleNCciAe5CkVr7Lf1TQ1R&oh=00_AfdkT8WTsHrH97zt5hZjgBLZlZi8YElY1nF-kuYR_gVMug&oe=6923ECAF","width":300},{"height":64,"url":"https://scontent-cdg4-3.xx.fbcdn.net/v/t1.6435-1/133114805_3507320386003279_5327632710500324798_n.jpg?stp=c0.0.1343.1343a_cp0_dst-jpg_s50x50_tt6&_nc_cat=106&ccb=1-7&_nc_sid=28885b&_nc_ohc=vC0osGnSDlwQ7kNvwGvrfRZ&_nc_oc=Adks8uj4lip0sJAt5s6hBruJJZS9NOeRJQRalEuVF4M0S0_FWykft9mRfcQWOhtm55nZ3ixQETeV2Hy-fBFf6oaE&_nc_zt=24&_nc_ht=scontent-cdg4-3.xx&edm=AP4hL3IEAAAA&_nc_gid=9Ro4i97lLR-RMwRcyFaE4w&_nc_tpa=Q5bMBQF-QKHh9F4W87tG6TN9IfR6-aUKTDcg4r-PdQ6E8tDW_bPiN62F5TWd7fKjcYQJ3QodEQgj&oh=00_AfdnwF3ROazIAjIueL-TZhXeqgZsYpDl4zFx2h_KZfKEdg&oe=6923ECAF","width":64}],"product":"premium","type":"user","uri":"spotify:user:11144377386"} Oct 25 09:50:39 volumio volumio[1282]: info: Spotify Successfully logged in Oct 25 09:50:39 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 25 09:50:39 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 25 09:50:39 volumio volumio[1282]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 09:50:39 volumio volumio[1282]: info: [1761378639688] CoreMusicLibrary::Adding element Spotify Oct 25 09:50:39 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 09:50:39 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 09:50:39 volumio systemd[1]: shairport-sync.service: Consumed 1.147s CPU time. Oct 25 09:50:39 volumio volumio[1282]: Cannot find translation for source YouTube2 Oct 25 09:50:39 volumio volumio[1282]: Cannot find translation for source YouTube Music Oct 25 09:50:39 volumio volumio[1282]: Cannot find translation for source Spotify Oct 25 09:50:39 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 09:50:39 volumio sudo[1816]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:39 volumio volumio[1282]: info: go-librespot daemon successfully initialized Oct 25 09:50:39 volumio sudo[1824]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 25 09:50:39 volumio sudo[1824]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:40 volumio volumio[1282]: info: Shairport-Sync Started Oct 25 09:50:40 volumio sudo[1840]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 25 09:50:40 volumio sudo[1840]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:40 volumio mpd[1765]: 2025-10-25T09:50:40 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 25 09:50:40 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 25 09:50:40 volumio sudo[1731]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:41 volumio volumio[1282]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 25 09:50:41 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 25 09:50:41 volumio mpd_monitor.sh[1873]: MPD Monitor Service: Starting MPD Monitor Service Oct 25 09:50:41 volumio sudo[1824]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:41 volumio sudo[1840]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:41 volumio volumio[1282]: info: CoreCommandRouter::volumioRetrievevolume Oct 25 09:50:41 volumio volumio[1282]: info: Successfully started MPD Monitor Oct 25 09:50:41 volumio volumio[1282]: info: Successfully started MPD Monitor Oct 25 09:50:41 volumio volumio[1282]: info: VolumeController:: Volume=66 Mute =false Oct 25 09:50:41 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:50:41 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:41 volumio volumio[1282]: info: CoreStateMachine::pushState Oct 25 09:50:41 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:41 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:50:41 volumio volumio[1282]: info: PeppySpectrum ---peppyspectrum status stop Oct 25 09:50:41 volumio sudo[1884]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Oct 25 09:50:41 volumio sudo[1884]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:41 volumio volumio[1282]: error: updateQueue error: null Oct 25 09:50:41 volumio sudo[1884]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:41 volumio volumio[1282]: info: peppyspectrum Daemon Stop Oct 25 09:50:41 volumio volumio[1282]: info: Completed starting Core Plugins Oct 25 09:50:41 volumio volumio[1282]: info: ------------------------------------------- Oct 25 09:50:41 volumio volumio[1282]: info: ----- MyVolumio plugins startup ---- Oct 25 09:50:41 volumio volumio[1282]: info: ------------------------------------------- Oct 25 09:50:41 volumio volumio[1282]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 25 09:50:42 volumio volumio[1282]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 25 09:50:42 volumio volumio[1282]: info: Initializing connection to go-librespot Websocket Oct 25 09:50:42 volumio go-librespot[1644]: time="2025-10-25T09:50:42+02:00" level=debug msg="new websocket client" Oct 25 09:50:42 volumio volumio[1282]: info: Connection to go-librespot Websocket established Oct 25 09:50:44 volumio sudo[1954]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 25 09:50:44 volumio sudo[1954]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:44 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 25 09:50:44 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 25 09:50:44 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 25 09:50:44 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 25 09:50:44 volumio mpd_monitor.sh[1957]: MPD Monitor Service: Starting MPD Monitor Service Oct 25 09:50:44 volumio sudo[1954]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:44 volumio volumio[1282]: info: Successfully started MPD Monitor Oct 25 09:50:45 volumio volumio[1282]: info: Getting Spotify volume Oct 25 09:50:45 volumio volumio[1282]: info: Spotify volume: 100 Oct 25 09:50:45 volumio volumio[1282]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Oct 25 09:50:46 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:50:46 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:50:46 volumio volumio[1282]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Oct 25 09:50:46 volumio volumio[1282]: SPOTIFY: SPOTIFY VOLUME 100 Oct 25 09:50:46 volumio volumio[1282]: SPOTIFY: VOLUMIO VOLUME 66 Oct 25 09:50:46 volumio volumio[1282]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 25 09:50:46 volumio volumio[1282]: info: Setting Spotify Volume from Volumio: 66 Oct 25 09:50:47 volumio volumio[1282]: SPOTIFY: SETTING SPOTIFY VOLUME 66 Oct 25 09:50:47 volumio volumio[1282]: info: Sending Spotify command with payload to local API: /player/volume Oct 25 09:50:47 volumio go-librespot[1644]: time="2025-10-25T09:50:47+02:00" level=debug msg="update volume requested to 43253/65535" Oct 25 09:50:47 volumio go-librespot[1644]: time="2025-10-25T09:50:47+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 25 09:50:47 volumio go-librespot[1644]: time="2025-10-25T09:50:47+02:00" level=trace msg="emitting websocket event: volume" Oct 25 09:50:47 volumio volumio[1282]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Oct 25 09:50:47 volumio volumio[1282]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 25 09:50:50 volumio volumio[1282]: info: Adding plugin bluetooth to MyMusic Plugins Oct 25 09:50:50 volumio volumio[1282]: info: Adding plugin multiroom to MyMusic Plugins Oct 25 09:50:50 volumio volumio[1282]: info: Adding plugin metavolumio to MyMusic Plugins Oct 25 09:50:50 volumio volumio[1282]: info: Adding plugin cd_controller to MyMusic Plugins Oct 25 09:50:50 volumio volumio[1282]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 25 09:50:50 volumio volumio[1282]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 25 09:50:50 volumio volumio[1282]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 25 09:50:50 volumio volumio[1282]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 25 09:50:54 volumio volumio[1282]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 25 09:50:54 volumio volumio[1282]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 25 09:50:54 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:54 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:50:54 volumio volumio[1282]: info: Starting MyVolumio Remote Streaming Endpoints Oct 25 09:50:54 volumio volumio[1282]: info: MyVolumio login type: Token Oct 25 09:50:54 volumio volumio[1282]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 25 09:50:54 volumio volumio[1282]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 25 09:50:57 volumio volumio[1282]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 25 09:50:57 volumio volumio[1282]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 25 09:50:57 volumio volumio[1282]: info: Streaming services startup Oct 25 09:50:57 volumio volumio[1282]: info: Starting Streaming Daemon Oct 25 09:50:57 volumio sudo[2017]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 25 09:50:57 volumio sudo[2017]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:50:57 volumio sudo[2017]: pam_unix(sudo:session): session closed for user root Oct 25 09:50:57 volumio volumio[1282]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 25 09:50:57 volumio volumio[1282]: error: Cannot start Volumio Streaming Daemon Oct 25 09:50:57 volumio volumio[1282]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 25 09:50:57 volumio volumio[1282]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 25 09:50:57 volumio volumio[1282]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Oct 25 09:50:57 volumio volumio[1282]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 13 Oct 25 09:50:57 volumio volumio[1282]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 14 Oct 25 09:50:58 volumio volumio[1282]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 15 Oct 25 09:50:59 volumio volumio[1282]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 25 09:51:00 volumio volumio[1282]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/141.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 16 Oct 25 09:51:00 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::volumioGetVisibleSources Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:01 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 25 09:51:01 volumio volumio[1282]: info: Received Get System Info Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 25 09:51:01 volumio volumio[1282]: info: Discovery: Getting this device information Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:01 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:01 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:01 volumio volumio[1282]: info: Listing playlists Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 25 09:51:01 volumio volumio[1282]: info: MyVolumio token set successfully Oct 25 09:51:01 volumio volumio[1282]: info: MYVOLUMIO: Adding device Oct 25 09:51:01 volumio volumio[1282]: info: MYVOLUMIO: Evaluating Server Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 25 09:51:01 volumio volumio[1282]: info: Received Get System Info Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 25 09:51:01 volumio volumio[1282]: info: Discovery: Getting this device information Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:01 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:01 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 25 09:51:02 volumio volumio[1282]: info: MyVolumio status changed Oct 25 09:51:02 volumio volumio[1282]: info: Streaming services startup Oct 25 09:51:02 volumio volumio[1282]: info: Starting Streaming Daemon Oct 25 09:51:02 volumio volumio[1282]: info: Removing browser output: myVolumio user plan is not superstar Oct 25 09:51:02 volumio volumio[1282]: info: Removing audio output: Oct 25 09:51:02 volumio volumio[1282]: info: Stoppping Tunnel 1 Oct 25 09:51:02 volumio sudo[2041]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 25 09:51:02 volumio sudo[2041]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:51:02 volumio sudo[2043]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 25 09:51:02 volumio sudo[2043]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:51:02 volumio sudo[2041]: pam_unix(sudo:session): session closed for user root Oct 25 09:51:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:51:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:51:02 volumio volumio[1282]: error: Cannot start Volumio Streaming Daemon Oct 25 09:51:02 volumio volumio[1282]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 25 09:51:02 volumio volumio[1282]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 25 09:51:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:51:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:51:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:51:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:51:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:51:02 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Oct 25 09:51:02 volumio sudo[2043]: pam_unix(sudo:session): session closed for user root Oct 25 09:51:02 volumio volumio[1282]: info: Remote SSH Stopped Oct 25 09:51:02 volumio volumio[1282]: info: Setting Geolocation for MyVolumio to eu6 Oct 25 09:51:02 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:51:02 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:51:02 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:51:02 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 25 09:51:02 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:51:02 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 25 09:51:02 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 25 09:51:03 volumio volumio-remote-updater[710]: Test mode disabled Oct 25 09:51:03 volumio volumio-remote-updater[710]: Alpha mode enabled Oct 25 09:51:03 volumio volumio-remote-updater[710]: Alpha legacy test mode disabled Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 25 09:51:03 volumio volumio[1282]: info: Successfully Added MyVolumio device Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 25 09:51:03 volumio volumio[1282]: info: Received Get System Info Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 25 09:51:03 volumio volumio[1282]: info: Discovery: Getting this device information Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:03 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 25 09:51:03 volumio volumio[1282]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 25 09:51:03 volumio volumio[1282]: info: Updating MyVolumio device info Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:51:03 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:51:04 volumio volumio[1282]: info: Successfully Updated MyVolumio device Oct 25 09:51:07 volumio go-librespot[1644]: time="2025-10-25T09:51:07+02:00" level=trace msg="sent dealer ping" Oct 25 09:51:07 volumio go-librespot[1644]: time="2025-10-25T09:51:07+02:00" level=trace msg="received dealer pong" Oct 25 09:51:09 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 25 09:51:09 volumio volumio[1282]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 17 Oct 25 09:51:09 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:09 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:10 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 25 09:51:11 volumio upmpdcli[2067]: writing RSA key Oct 25 09:51:14 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:51:14 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:51:14 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 25 09:51:14 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 25 09:51:14 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 25 09:51:14 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 25 09:51:14 volumio volumio[1282]: info: CoreCommandRouter::volumioGetBrowseSources Oct 25 09:51:14 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 25 09:51:17 volumio volumio[1282]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 25 09:51:17 volumio volumio[1282]: info: Completed starting MyVolumio Plugin Oct 25 09:51:17 volumio volumio[1282]: [Metrics] CommandRouter: 66s 889.69ms Oct 25 09:51:17 volumio volumio[1282]: info: CoreCommandRouter::volumiosetStartupVolume Oct 25 09:51:17 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 09:51:17 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 09:51:17 volumio volumio[1282]: info: CoreCommandRouter::Close All Modals sent Oct 25 09:51:17 volumio volumio[1282]: info: CoreCommandRouter::Close All Modals sent Oct 25 09:51:18 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 25 09:51:18 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 25 09:51:18 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 25 09:51:24 volumio volumio[1282]: info: BOOT COMPLETED Oct 25 09:51:29 volumio volumio[1282]: verbose: New Socket.io Connection to 192.168.178.74 from 192.168.178.113 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7 Pro Build/BP3A.251005.004.B1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/141.0.7390.97 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 18 Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::volumioGetVisibleSources Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:29 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::volumioGetQueue Oct 25 09:51:29 volumio volumio[1282]: info: CoreStateMachine::getQueue Oct 25 09:51:29 volumio volumio[1282]: info: CorePlayQueue::getQueue Oct 25 09:51:29 volumio volumio[1282]: info: Listing playlists Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 25 09:51:29 volumio volumio[1282]: info: Received Get System Info Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 25 09:51:29 volumio volumio[1282]: info: Discovery: Getting this device information Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:29 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:29 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:29 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 25 09:51:35 volumio go-librespot[1644]: time="2025-10-25T09:51:35+02:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/37i9dQZF1DX4JAvHpjipBk" Oct 25 09:51:35 volumio go-librespot[1644]: time="2025-10-25T09:51:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 137" Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=debug msg="handling transfer player command from 3d7d6ac52e2b1ea5152b865f749f10f0438c6012" Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=debug msg="resolved context of track" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=debug msg="loading track (paused: false, position: 151486ms)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=trace msg="sent dealer ping" Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=trace msg="emitting websocket event: will_play" Oct 25 09:51:37 volumio volumio[1282]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","play_origin":"go-librespot"}} Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=debug msg="selected format OGG_VORBIS_320 (91a4ee4d47dcdb17b77c91e5af0db5c533e932c6)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=debug msg="requested aes key for file 91a4ee4d47dcdb17b77c91e5af0db5c533e932c6, gid: 09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:37 volumio go-librespot[1644]: time="2025-10-25T09:51:37+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="fetched first chunk of 12, total size is 6291384 bytes" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="fetched chunk 11/11, size: 524216" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=trace msg="seek to 140000ms (diff: 215ms, samples: 6174000, bytes: 6279418)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="created new output device" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 159" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=info msg="loaded track \"Thank You (Not So Bad)\" (paused: false, position: 151486ms, duration: 140000ms, prefetched: false)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=trace msg="emitting websocket event: metadata" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=trace msg="emitting websocket event: active" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="sending successful reply for dealer request" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=trace msg="received dealer pong" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Oct 25 09:51:38 volumio volumio[1282]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","name":"Thank You (Not So Bad)","artist_names":["Dimitri Vegas \u0026 Like Mike","Tiësto","Dido","W\u0026W","Dimitri Vegas","Like Mike"],"album_name":"Thank You (Not So Bad)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","position":151486,"duration":140000,"release_date":"year:2023 month:12 day:1","track_number":1,"disc_number":1}} Oct 25 09:51:38 volumio volumio[1282]: SPOTIFY: received: {"type":"active","data":null} Oct 25 09:51:38 volumio volumio[1282]: info: Aligning Spotify Volume to Volumio Volume Oct 25 09:51:38 volumio volumio[1282]: info: CoreCommandRouter::volumioGetState Oct 25 09:51:38 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:38 volumio volumio[1282]: info: Setting Spotify Volume from Volumio: 66 Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=trace msg="emitting websocket event: playing" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=trace msg="emitting websocket event: not_playing" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="loading track (paused: true, position: 1ms)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio volumio[1282]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","resume":false,"play_origin":"go-librespot"}} Oct 25 09:51:38 volumio volumio[1282]: SPOTIFY: PUSH STATE SPOTIFY Oct 25 09:51:38 volumio volumio[1282]: SPOTIFY: {"status":"play","service":"spop","title":"Thank You (Not So Bad)","artist":"Dimitri Vegas & Like Mike, Tiësto, Dido, W&W, Dimitri Vegas, Like Mike","album":"Thank You (Not So Bad)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","trackType":"spotify","seek":151486,"duration":140,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 25 09:51:38 volumio volumio[1282]: info: CoreCommandRouter::servicePushState Oct 25 09:51:38 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:38 volumio volumio[1282]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Thank You (Not So Bad)","artist":"Dimitri Vegas & Like Mike, Tiësto, Dido, W&W, Dimitri Vegas, Like Mike","album":"Thank You (Not So Bad)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","trackType":"spotify","seek":151486,"duration":140,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 25 09:51:38 volumio volumio[1282]: verbose: CURRENT POSITION 0 Oct 25 09:51:38 volumio volumio[1282]: info: CoreStateMachine::syncState stateService play Oct 25 09:51:38 volumio volumio[1282]: info: CoreStateMachine::syncState currentStatus stop Oct 25 09:51:38 volumio volumio[1282]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","play_origin":"go-librespot"}} Oct 25 09:51:38 volumio volumio[1282]: error: Failed to decode event: not_playing Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=trace msg="emitting websocket event: will_play" Oct 25 09:51:38 volumio volumio[1282]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","play_origin":"go-librespot"}} Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="selected format OGG_VORBIS_320 (91a4ee4d47dcdb17b77c91e5af0db5c533e932c6)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="requested aes key for file 91a4ee4d47dcdb17b77c91e5af0db5c533e932c6, gid: 09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=debug msg="fetched first chunk of 12, total size is 6291384 bytes" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=trace msg="seek to 1ms (diff: -225ms, samples: 44, bytes: 14539)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio go-librespot[1644]: time="2025-10-25T09:51:38+02:00" level=info msg="loaded track \"Thank You (Not So Bad)\" (paused: true, position: 1ms, duration: 140000ms, prefetched: false)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:38 volumio volumio[1282]: SPOTIFY: PUSH STATE SPOTIFY Oct 25 09:51:38 volumio volumio[1282]: SPOTIFY: {"status":"play","service":"spop","title":"Thank You (Not So Bad)","artist":"Dimitri Vegas & Like Mike, Tiësto, Dido, W&W, Dimitri Vegas, Like Mike","album":"Thank You (Not So Bad)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","trackType":"spotify","seek":151486,"duration":140,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::servicePushState Oct 25 09:51:39 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:39 volumio volumio[1282]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Thank You (Not So Bad)","artist":"Dimitri Vegas & Like Mike, Tiësto, Dido, W&W, Dimitri Vegas, Like Mike","album":"Thank You (Not So Bad)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","trackType":"spotify","seek":151486,"duration":140,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 25 09:51:39 volumio volumio[1282]: verbose: CURRENT POSITION 0 Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::syncState stateService play Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::syncState currentStatus play Oct 25 09:51:39 volumio volumio[1282]: info: Received an update from plugin. extracting info from payload Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::pushState Oct 25 09:51:39 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:51:39 volumio go-librespot[1644]: time="2025-10-25T09:51:39+02:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::pushState Oct 25 09:51:39 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:51:39 volumio volumio[1282]: info: PeppySpectrum ---peppyspectrum status play Oct 25 09:51:39 volumio volumio[1282]: info: PeppySpectrum ---peppyspectrum status play Oct 25 09:51:39 volumio go-librespot[1644]: time="2025-10-25T09:51:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 09:51:39 volumio go-librespot[1644]: time="2025-10-25T09:51:39+02:00" level=trace msg="emitting websocket event: metadata" Oct 25 09:51:39 volumio go-librespot[1644]: time="2025-10-25T09:51:39+02:00" level=trace msg="emitting websocket event: stopped" Oct 25 09:51:39 volumio go-librespot[1644]: time="2025-10-25T09:51:39+02:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:39 volumio volumio[1282]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Oct 25 09:51:39 volumio sudo[2128]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Oct 25 09:51:39 volumio sudo[2128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:51:39 volumio sudo[2130]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Oct 25 09:51:39 volumio sudo[2130]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:51:39 volumio go-librespot[1644]: time="2025-10-25T09:51:39+02:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:39 volumio go-librespot[1644]: time="2025-10-25T09:51:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 09:51:39 volumio go-librespot[1644]: time="2025-10-25T09:51:39+02:00" level=trace msg="emitting websocket event: paused" Oct 25 09:51:39 volumio volumio[1282]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Oct 25 09:51:39 volumio volumio[1282]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","name":"Thank You (Not So Bad)","artist_names":["Dimitri Vegas \u0026 Like Mike","Tiësto","Dido","W\u0026W","Dimitri Vegas","Like Mike"],"album_name":"Thank You (Not So Bad)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","position":1,"duration":140000,"release_date":"year:2023 month:12 day:1","track_number":1,"disc_number":1}} Oct 25 09:51:39 volumio volumio[1282]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}} Oct 25 09:51:39 volumio volumio[1282]: SPOTIFY: PUSH STATE SPOTIFY Oct 25 09:51:39 volumio volumio[1282]: SPOTIFY: {"status":"stop","service":"spop","title":"Thank You (Not So Bad)","artist":"Dimitri Vegas & Like Mike, Tiësto, Dido, W&W, Dimitri Vegas, Like Mike","album":"Thank You (Not So Bad)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","trackType":"spotify","seek":1,"duration":140,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::servicePushState Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::pushState Oct 25 09:51:39 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:51:39 volumio systemd[1]: Started peppyspectrum.service - peppyspectrum Daemon. Oct 25 09:51:39 volumio sudo[2130]: pam_unix(sudo:session): session closed for user root Oct 25 09:51:39 volumio sudo[2128]: pam_unix(sudo:session): session closed for user root Oct 25 09:51:39 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:39 volumio volumio[1282]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"Thank You (Not So Bad)","artist":"Dimitri Vegas & Like Mike, Tiësto, Dido, W&W, Dimitri Vegas, Like Mike","album":"Thank You (Not So Bad)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","trackType":"spotify","seek":1,"duration":140,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 25 09:51:39 volumio volumio[1282]: verbose: CURRENT POSITION 0 Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::syncState stateService stop Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::syncState currentStatus play Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::stPlaybackTimer Oct 25 09:51:39 volumio volumio[1282]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","play_origin":"go-librespot"}} Oct 25 09:51:39 volumio volumio[1282]: SPOTIFY: PUSH STATE SPOTIFY Oct 25 09:51:39 volumio volumio[1282]: SPOTIFY: {"status":"pause","service":"spop","title":"Thank You (Not So Bad)","artist":"Dimitri Vegas & Like Mike, Tiësto, Dido, W&W, Dimitri Vegas, Like Mike","album":"Thank You (Not So Bad)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","trackType":"spotify","seek":1,"duration":140,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::servicePushState Oct 25 09:51:39 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:39 volumio volumio[1282]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Thank You (Not So Bad)","artist":"Dimitri Vegas & Like Mike, Tiësto, Dido, W&W, Dimitri Vegas, Like Mike","album":"Thank You (Not So Bad)","albumart":"https://i.scdn.co/image/ab67616d00001e020aa08f8923434aab06e43b37","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","trackType":"spotify","seek":1,"duration":140,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 25 09:51:39 volumio volumio[1282]: verbose: CURRENT POSITION 0 Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::syncState stateService pause Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::syncState currentStatus stop Oct 25 09:51:39 volumio volumio[1282]: info: CoreStateMachine::pushState Oct 25 09:51:39 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 25 09:51:39 volumio volumio[1282]: info: CoreCommandRouter::volumioPushState Oct 25 09:51:39 volumio volumio[1282]: info: PeppySpectrum ---peppyspectrum status play Oct 25 09:51:39 volumio volumio[1282]: info: PeppySpectrum ---peppyspectrum status stop Oct 25 09:51:39 volumio sudo[2136]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Oct 25 09:51:39 volumio sudo[2136]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:51:39 volumio volumio[1282]: info: PeppySpectrum ---peppyspectrum status stop Oct 25 09:51:40 volumio sudo[2136]: pam_unix(sudo:session): session closed for user root Oct 25 09:51:40 volumio volumio[1282]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Oct 25 09:51:40 volumio volumio[1282]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Oct 25 09:51:40 volumio volumio[1282]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Oct 25 09:51:40 volumio sudo[2139]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Oct 25 09:51:40 volumio sudo[2139]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:51:40 volumio volumio[1282]: info: peppyspectrum Daemon Started Oct 25 09:51:40 volumio volumio[1282]: info: peppyspectrum Daemon Started Oct 25 09:51:40 volumio volumio[1282]: SPOTIFY: SETTING SPOTIFY VOLUME 66 Oct 25 09:51:40 volumio volumio[1282]: info: Sending Spotify command with payload to local API: /player/volume Oct 25 09:51:40 volumio systemd[1]: Stopping peppyspectrum.service - peppyspectrum Daemon... Oct 25 09:51:40 volumio sudo[2141]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Oct 25 09:51:40 volumio sudo[2141]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 09:51:40 volumio systemd[1]: peppyspectrum.service: Deactivated successfully. Oct 25 09:51:40 volumio systemd[1]: Stopped peppyspectrum.service - peppyspectrum Daemon. Oct 25 09:51:40 volumio sudo[2139]: pam_unix(sudo:session): session closed for user root Oct 25 09:51:40 volumio go-librespot[1644]: time="2025-10-25T09:51:40+02:00" level=debug msg="update volume requested to 43253/65535" Oct 25 09:51:40 volumio volumio[1282]: info: peppyspectrum Daemon Started Oct 25 09:51:40 volumio sudo[2141]: pam_unix(sudo:session): session closed for user root Oct 25 09:51:40 volumio volumio[1282]: info: touch_display: Setting screensaver timeout to 120 seconds. Oct 25 09:51:40 volumio volumio[1282]: info: peppyspectrum Daemon Stop Oct 25 09:51:40 volumio volumio[1282]: info: peppyspectrum Daemon Stop Oct 25 09:51:40 volumio go-librespot[1644]: time="2025-10-25T09:51:40+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 25 09:51:40 volumio go-librespot[1644]: time="2025-10-25T09:51:40+02:00" level=trace msg="emitting websocket event: volume" Oct 25 09:51:40 volumio volumio[1282]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Oct 25 09:51:40 volumio volumio[1282]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Oct 25 09:51:47 volumio go-librespot[1644]: time="2025-10-25T09:51:47+02:00" level=debug msg="handling resume player command from 3d7d6ac52e2b1ea5152b865f749f10f0438c6012" Oct 25 09:51:47 volumio go-librespot[1644]: time="2025-10-25T09:51:47+02:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:47 volumio go-librespot[1644]: time="2025-10-25T09:51:47+02:00" level=trace msg="seek to 1ms (diff: -225ms, samples: 44, bytes: 14539)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:47 volumio go-librespot[1644]: time="2025-10-25T09:51:47+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Oct 25 09:51:47 volumio go-librespot[1644]: time="2025-10-25T09:51:47+02:00" level=debug msg="resume track at 226ms" Oct 25 09:51:47 volumio go-librespot[1644]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Oct 25 09:51:47 volumio go-librespot[1643]: Aborted Oct 25 09:51:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Oct 25 09:51:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 09:51:47 volumio volumio[1282]: info: Connection to go-librespot Websocket closed Oct 25 09:51:50 volumio volumio[1282]: info: Initializing connection to go-librespot Websocket Oct 25 09:51:50 volumio volumio[1282]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 25 09:51:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Oct 25 09:51:50 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 09:51:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 09:51:50 volumio go-librespot[2181]: go-librespot daemon starting... Oct 25 09:51:50 volumio go-librespot[2182]: time="2025-10-25T09:51:50+02:00" level=info msg="running go-librespot 0.4.0" Oct 25 09:51:50 volumio go-librespot[2182]: time="2025-10-25T09:51:50+02:00" level=debug msg="app state loaded" Oct 25 09:51:50 volumio go-librespot[2182]: time="2025-10-25T09:51:50+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 09:51:50 volumio go-librespot[2182]: time="2025-10-25T09:51:50+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 25 09:51:50 volumio go-librespot[2182]: time="2025-10-25T09:51:50+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 25 09:51:50 volumio go-librespot[2182]: time="2025-10-25T09:51:50+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 25 09:51:50 volumio go-librespot[2182]: time="2025-10-25T09:51:50+02:00" level=info msg="zeroconf server listening on port 46443" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="obtained new client token: AAByWiDT9+5kZToheAIzO9ngK1UA5XCWaoDrv8flH8APLepSlJ6qf0seAseSJkV1vwBkVo6MSAs7SgSvMpUQNQQ6HZCz6W5o7YmLWXn90uJvFC8ygb9MHaHeGbzAAbKyLxw7S6zKPRkp54lyZyewgvu6XeUF1PmMO19moWMSFqWJieTOlp1GNADTDKwG+3uz603OxiscnjdvnaedcS9YijL5ixns0c93yPBgLSyJqYjHnLmSyz+IABE=" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="completed keyexchange" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="completed challenge" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=info msg="authenticated AP" username="11*******86" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=info msg="authenticated Login5" username="11*******86" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="initializing zeroconf session" username="11*******86" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="dealer connection opened" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=trace msg="starting accesspoint recv loop" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=trace msg="starting dealer recv loop" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=trace msg="received accesspoint ping" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="received connection id: YjY0MzAyNDQtYmYy...QzI2RkFGMEZBRg==" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=trace msg="received accesspoint pong ack" Oct 25 09:51:51 volumio go-librespot[2182]: time="2025-10-25T09:51:51+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 25 09:51:53 volumio volumio[1282]: info: Initializing connection to go-librespot Websocket Oct 25 09:51:53 volumio go-librespot[2182]: time="2025-10-25T09:51:53+02:00" level=debug msg="new websocket client" Oct 25 09:51:53 volumio volumio[1282]: info: Connection to go-librespot Websocket established Oct 25 09:51:55 volumio volumio[1282]: info: CoreCommandRouter::volumioPlay Oct 25 09:51:55 volumio volumio[1282]: info: CoreStateMachine::play index undefined Oct 25 09:51:55 volumio volumio[1282]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 25 09:51:55 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:55 volumio volumio[1282]: info: CoreStateMachine::startPlaybackTimer Oct 25 09:51:55 volumio volumio[1282]: info: CorePlayQueue::getTrack 0 Oct 25 09:51:55 volumio volumio[1282]: info: [1761378715866] ControllerSpotify::clearAddPlayTrack Oct 25 09:51:55 volumio volumio[1282]: info: Sending Spotify command with payload to local API: /player/play Oct 25 09:51:55 volumio go-librespot[2182]: time="2025-10-25T09:51:55+02:00" level=debug msg="resolved context of track" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:55 volumio go-librespot[2182]: time="2025-10-25T09:51:55+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:55 volumio go-librespot[2182]: time="2025-10-25T09:51:55+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=trace msg="emitting websocket event: will_play" Oct 25 09:51:56 volumio volumio[1282]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","uri":"spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt","play_origin":"go-librespot"}} Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 391" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2234" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="selected format OGG_VORBIS_320 (91a4ee4d47dcdb17b77c91e5af0db5c533e932c6)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="requested aes key for file 91a4ee4d47dcdb17b77c91e5af0db5c533e932c6, gid: 09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="fetched first chunk of 12, total size is 6291384 bytes" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="created new output device" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Oct 25 09:51:56 volumio go-librespot[2182]: time="2025-10-25T09:51:56+02:00" level=info msg="loaded track \"Thank You (Not So Bad)\" (paused: false, position: 0ms, duration: 140000ms, prefetched: false)" uri="spotify:track:09CnYHiZ5jGT1wr1TXJ9Zt" Oct 25 09:51:56 volumio volumio[1282]: info: Getting Spotify volume Oct 25 09:51:56 volumio go-librespot[2182]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Oct 25 09:51:56 volumio volumio[1282]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Oct 25 09:51:56 volumio volumio[1282]: info: Connection to go-librespot Websocket closed Oct 25 09:51:56 volumio go-librespot[2181]: Aborted Oct 25 09:51:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Oct 25 09:51:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 25 09:51:56 volumio volumio[1282]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 25 09:51:56 volumio volumio[1282]: Error: read ECONNRESET Oct 25 09:51:56 volumio volumio[1282]: at TCP.onStreamRead (node:internal/stream_base_commons:217:20) { Oct 25 09:51:56 volumio volumio[1282]: errno: -104, Oct 25 09:51:56 volumio volumio[1282]: code: 'ECONNRESET', Oct 25 09:51:56 volumio volumio[1282]: syscall: 'read', Oct 25 09:51:56 volumio volumio[1282]: response: undefined Oct 25 09:51:56 volumio volumio[1282]: } Oct 25 09:51:56 volumio volumio[1282]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 25 09:51:58 volumio sudo[2220]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-25 09:50' Oct 25 09:51:58 volumio sudo[2220]: 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="c22b72a8acb34a699a626adb0a09a6b88ee7233a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="40400d6a6fa57cf20e36499e510876b3654e9c4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Oct 4 16:40:08 UTC 2025" VOLUMIO_VERSION="4.061" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7f8ace80645f85765fa10c72d1769d04"