Jun 13 22:51:01 volumio volumio[1206]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 13 22:51:01 volumio volumio[1206]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 13 22:51:07 volumio volumio[1206]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 13 22:51:08 volumio volumio[1206]: info: CALLMETHOD: music_service spop logout Jun 13 22:51:08 volumio volumio[1206]: info: CoreCommandRouter::executeOnPlugin: spop , logout Jun 13 22:51:08 volumio volumio[1206]: info: Deleting Spotify credentials File Jun 13 22:51:08 volumio volumio[1206]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Jun 13 22:51:08 volumio volumio[1206]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:08 volumio volumio[1206]: Cannot find translation for source YouTube2 Jun 13 22:51:08 volumio volumio[1206]: Cannot find translation for source YouTube Music Jun 13 22:51:09 volumio volumio[1206]: info: Creating Spotify config file Jun 13 22:51:09 volumio volumio[1206]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:09 volumio volumio[1206]: info: Spotify config file written Jun 13 22:51:09 volumio sudo[2498]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 13 22:51:09 volumio sudo[2498]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:09 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jun 13 22:51:09 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jun 13 22:51:09 volumio systemd[1]: go-librespot-daemon.service: Killing process 2327 (go-librespot) with signal SIGKILL. Jun 13 22:51:09 volumio systemd[1]: go-librespot-daemon.service: Killing process 2330 (go-librespot) with signal SIGKILL. Jun 13 22:51:09 volumio systemd[1]: go-librespot-daemon.service: Killing process 2331 (go-librespot) with signal SIGKILL. Jun 13 22:51:09 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jun 13 22:51:09 volumio volumio[1206]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 13 22:51:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 13 22:51:09 volumio volumio[1206]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jun 13 22:51:09 volumio volumio[1206]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 13 22:51:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 13 22:51:09 volumio go-librespot[2504]: go-librespot daemon starting... Jun 13 22:51:09 volumio sudo[2498]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:09 volumio volumio[1206]: Error: socket hang up Jun 13 22:51:09 volumio volumio[1206]: at connResetException (node:internal/errors:720:14) Jun 13 22:51:09 volumio volumio[1206]: at Socket.socketOnEnd (node:_http_client:519:23) Jun 13 22:51:09 volumio volumio[1206]: at Socket.emit (node:events:526:35) Jun 13 22:51:09 volumio volumio[1206]: at endReadableNT (node:internal/streams/readable:1376:12) Jun 13 22:51:09 volumio volumio[1206]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jun 13 22:51:09 volumio volumio[1206]: code: 'ECONNRESET', Jun 13 22:51:09 volumio volumio[1206]: response: undefined Jun 13 22:51:09 volumio volumio[1206]: } Jun 13 22:51:09 volumio volumio[1206]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 13 22:51:09 volumio dbus-daemon[855]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.40' (uid=0 pid=2502 comm="timedatectl show --property=NTPSynchronized --valu") Jun 13 22:51:09 volumio go-librespot[2505]: time="2025-06-13T22:51:09-07:00" level=info msg="running go-librespot 0.2.0" Jun 13 22:51:09 volumio go-librespot[2505]: time="2025-06-13T22:51:09-07:00" level=debug msg="no app state found" Jun 13 22:51:09 volumio go-librespot[2505]: time="2025-06-13T22:51:09-07:00" level=debug msg="stored credentials not found" Jun 13 22:51:09 volumio go-librespot[2505]: time="2025-06-13T22:51:09-07:00" level=info msg="generated new device id: e5c741bdbffc9419c6aa553a2254bbe9d065a5b5" Jun 13 22:51:09 volumio go-librespot[2505]: time="2025-06-13T22:51:09-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 13 22:51:09 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jun 13 22:51:09 volumio dbus-daemon[855]: [system] Successfully activated service 'org.freedesktop.timedate1' Jun 13 22:51:09 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Jun 13 22:51:09 volumio setdatetime-helper.sh[2501]: Time is not synchronized. Attempting to sync... Jun 13 22:51:09 volumio go-librespot[2505]: time="2025-06-13T22:51:09-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 13 22:51:09 volumio go-librespot[2505]: time="2025-06-13T22:51:09-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 13 22:51:09 volumio go-librespot[2505]: time="2025-06-13T22:51:09-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 13 22:51:09 volumio go-librespot[2505]: time="2025-06-13T22:51:09-07:00" level=info msg="zeroconf server listening on port 40193" Jun 13 22:51:09 volumio sudo[2531]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Sat, 14 Jun 2025 05:51:09 GMT#015' Jun 13 22:51:09 volumio sudo[2531]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 13 22:51:09 volumio setdatetime-helper.sh[2532]: Fri Jun 13 22:51:09 PDT 2025 Jun 13 22:51:09 volumio sudo[2531]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:09 volumio setdatetime-helper.sh[2501]: Time synchronized successfully. Jun 13 22:51:09 volumio systemd-journald[445]: Time jumped backwards, rotating. Jun 13 22:51:09 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jun 13 22:51:09 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jun 13 22:51:09 volumio sudo[2536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-06-13 22:50' Jun 13 22:51:09 volumio sudo[2536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:09 volumio sudo[2536]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:09 volumio volumio-remote-updater[885]: [2025-06-13 22:51:09] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jun 13 22:51:09 volumio volumio-remote-updater[885]: [2025-06-13 22:51:09] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jun 13 22:51:09 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jun 13 22:51:09 volumio systemd[1]: media-TESLADRIVE.mount: Deactivated successfully. Jun 13 22:51:09 volumio ntfs-3g[1288]: Unmounting /dev/sda1 (TESLADRIVE) Jun 13 22:51:09 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jun 13 22:51:09 volumio systemd[1]: volumio.service: Consumed 26.857s CPU time. Jun 13 22:51:09 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 13 22:51:09 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 13 22:51:10 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Jun 13 22:51:10 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 13 22:51:10 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jun 13 22:51:10 volumio systemd[1]: volumio.service: Consumed 26.857s CPU time. Jun 13 22:51:10 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jun 13 22:51:10 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 13 22:51:10 volumio volumio[2575]: info: ------------------------------------------- Jun 13 22:51:10 volumio volumio[2575]: info: ----- Volumio3 ---- Jun 13 22:51:10 volumio volumio[2575]: info: ------------------------------------------- Jun 13 22:51:10 volumio volumio[2575]: info: ----- System startup ---- Jun 13 22:51:10 volumio volumio[2575]: info: ------------------------------------------- Jun 13 22:51:10 volumio volumio[2575]: info: MYVOLUMIO Environment detected Jun 13 22:51:10 volumio volumio[2575]: info: Plugin folders cleanup Jun 13 22:51:10 volumio volumio[2575]: info: Scanning into folder /volumio/app/plugins/ Jun 13 22:51:10 volumio volumio[2575]: info: Scanning category audio_interface Jun 13 22:51:10 volumio volumio[2575]: info: Scanning category miscellanea Jun 13 22:51:10 volumio volumio[2575]: info: Scanning category music_service Jun 13 22:51:10 volumio volumio[2575]: info: Scanning category plugins.json Jun 13 22:51:10 volumio volumio[2575]: info: Scanning category system_controller Jun 13 22:51:10 volumio volumio[2575]: info: Scanning category user_interface Jun 13 22:51:10 volumio volumio[2575]: info: Scanning into folder /data/plugins/ Jun 13 22:51:10 volumio volumio[2575]: info: Scanning category music_service Jun 13 22:51:10 volumio volumio[2575]: info: Scanning category system_controller Jun 13 22:51:10 volumio volumio[2575]: info: Scanning category user_interface Jun 13 22:51:10 volumio volumio[2575]: info: Plugin folders cleanup completed Jun 13 22:51:10 volumio volumio[2575]: info: ------------------------------------------- Jun 13 22:51:10 volumio volumio[2575]: info: ----- Core plugins startup ---- Jun 13 22:51:10 volumio volumio[2575]: info: ------------------------------------------- Jun 13 22:51:10 volumio volumio[2575]: info: Loading plugins from folder /volumio/app/plugins/ Jun 13 22:51:10 volumio volumio[2575]: info: Adding plugin upnp to MyMusic Plugins Jun 13 22:51:10 volumio volumio[2575]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 13 22:51:10 volumio volumio[2575]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 13 22:51:10 volumio volumio[2575]: info: Loading plugins from folder /data/plugins/ Jun 13 22:51:10 volumio volumio[2575]: info: Loading plugin "system"... Jun 13 22:51:10 volumio volumio[2575]: info: Loading plugin "appearance"... Jun 13 22:51:11 volumio volumio[2575]: info: Loading plugin "network"... Jun 13 22:51:11 volumio volumio[2575]: info: Refreshing Cached IP Addresses Jun 13 22:51:11 volumio sudo[2604]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 13 22:51:11 volumio sudo[2604]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:11 volumio sudo[2606]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 13 22:51:11 volumio volumio[2575]: info: Loading plugin "services"... Jun 13 22:51:11 volumio sudo[2606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:11 volumio sudo[2604]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:11 volumio volumio[2575]: info: Loading plugin "alsa_controller"... Jun 13 22:51:11 volumio sudo[2606]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:11 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 13 22:51:11 volumio volumio[2575]: info: Loading plugin "wizard"... Jun 13 22:51:11 volumio volumio[2575]: info: Loading plugin "networkfs"... Jun 13 22:51:11 volumio volumio[2575]: info: Starting Udev Watcher for removable devices Jun 13 22:51:11 volumio volumio[2575]: info: Mounting Device TESLADRIVE Jun 13 22:51:11 volumio sudo[2637]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/TESLADRIVE -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Jun 13 22:51:11 volumio sudo[2637]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:13 volumio ntfs-3g[2640]: Version 2022.10.3 integrated FUSE 28 Jun 13 22:51:13 volumio ntfs-3g[2640]: Mounted /dev/sda1 (Read-Write, label "TESLADRIVE", NTFS 3.1) Jun 13 22:51:13 volumio ntfs-3g[2640]: Cmdline options: rw,noatime,dmask=0000,fmask=0000,iocharset=utf8 Jun 13 22:51:13 volumio ntfs-3g[2640]: Mount options: iocharset=utf8,allow_other,nonempty,noatime,rw,default_permissions,fsname=/dev/sda1,blkdev,blksize=4096 Jun 13 22:51:13 volumio ntfs-3g[2640]: Global ownership and permissions enforced, configuration type 7 Jun 13 22:51:13 volumio sudo[2637]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:13 volumio volumio[2575]: info: Mounting Device MUSIC Jun 13 22:51:13 volumio sudo[2649]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sdb1 /mnt/USB/MUSIC -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Jun 13 22:51:13 volumio sudo[2649]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:13 volumio sudo[2649]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:13 volumio volumio[2575]: mount: /media/MUSIC: /dev/sdb1 already mounted on /media/MUSIC. Jun 13 22:51:13 volumio volumio[2575]: dmesg(1) may have more information after failed mount system call. Jun 13 22:51:13 volumio volumio[2575]: error: Failed to mount MUSIC: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sdb1" "/mnt/USB/MUSIC" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Jun 13 22:51:13 volumio volumio[2575]: mount: /media/MUSIC: /dev/sdb1 already mounted on /media/MUSIC. Jun 13 22:51:13 volumio volumio[2575]: dmesg(1) may have more information after failed mount system call. Jun 13 22:51:13 volumio volumio[2575]: info: Ignoring mount for partition: boot Jun 13 22:51:13 volumio volumio[2575]: info: Ignoring mount for partition: volumio Jun 13 22:51:13 volumio volumio[2575]: info: Ignoring mount for partition: volumio_data Jun 13 22:51:13 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "volumio_command_line_client"... Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "upnp"... Jun 13 22:51:13 volumio volumio[2575]: info: [1749880273258] Starting Upmpd Daemon Jun 13 22:51:13 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "my_music"... Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "mpd"... Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "upnp_browser"... Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "alarm-clock"... Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "airplay_emulation"... Jun 13 22:51:13 volumio volumio[2575]: info: Starting Shairport Sync Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "last_100"... Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "webradio"... Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "i2s_dacs"... Jun 13 22:51:13 volumio volumio[2575]: info: I2S DAC not set, start Auto-detection Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "volumiodiscovery"... Jun 13 22:51:13 volumio volumio[2575]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 13 22:51:13 volumio volumio[2575]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 13 22:51:13 volumio volumio[2575]: *** WARNING *** For more information see Jun 13 22:51:13 volumio volumio[2575]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 13 22:51:13 volumio volumio[2575]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 13 22:51:13 volumio volumio[2575]: *** WARNING *** For more information see Jun 13 22:51:13 volumio node[2575]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 13 22:51:13 volumio node[2575]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 13 22:51:13 volumio node[2575]: *** WARNING *** For more information see Jun 13 22:51:13 volumio node[2575]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 13 22:51:13 volumio node[2575]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 13 22:51:13 volumio node[2575]: *** WARNING *** For more information see Jun 13 22:51:13 volumio volumio[2575]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 13 22:51:13 volumio volumio[2575]: info: Discovery: Started advertising with name: Volumio Jun 13 22:51:13 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 13 22:51:13 volumio volumio[2575]: info: Loading plugin "spop"... Jun 13 22:51:14 volumio volumio[2575]: info: Loading plugin "youtube2"... Jun 13 22:51:14 volumio volumio-remote-updater[885]: [2025-06-13 22:51:14] [connect] Successful connection Jun 13 22:51:14 volumio volumio[2575]: info: Loading plugin "ytmusic"... Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "SleepWakePlugin"... Jun 13 22:51:15 volumio volumio[2575]: info: Applying required configuration parameters for plugin SleepWakePlugin Jun 13 22:51:15 volumio volumio[2575]: info: SleepWakePlugin - onVolumioStart Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "outputs"... Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "albumart"... Jun 13 22:51:15 volumio volumio[2575]: info: Plugin example_plugin is not enabled Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "inputs"... Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "updater_comm"... Jun 13 22:51:15 volumio volumio[2575]: info: Plugin mpdemulation is not enabled Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "rest_api"... Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "websocket"... Jun 13 22:51:15 volumio volumio[2575]: info: Starting Socket.io Server version 1.7.4 Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "backup_restore"... Jun 13 22:51:15 volumio volumio[2575]: info: Applying required configuration parameters for plugin backup_restore Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "Systeminfo"... Jun 13 22:51:15 volumio volumio[2653]: Forking 3 albumart workers Jun 13 22:51:15 volumio volumio[2575]: info: Plugin peppymeterbasic is not enabled Jun 13 22:51:15 volumio volumio[2575]: info: Loading plugin "peppyspectrum"... Jun 13 22:51:15 volumio volumio[2575]: info: Loading i18n strings for locale en Jun 13 22:51:15 volumio volumio[2575]: Updating browse sources language Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::initPlayerControls Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: Express server listening on port 3000 Jun 13 22:51:16 volumio volumio[2575]: [Metrics] WebUI: 5s 572.75ms Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::resetVolumioState Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::getcurrentVolume Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioRetrievevolume Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: Volumio Network Manager: Network status updated: 1 Jun 13 22:51:16 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254:3000 from 192.168.1.247 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 1 Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::pushState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioPushState Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::updateTrackBlock Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrackBlock Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioRetrievevolume Jun 13 22:51:16 volumio volumio[2575]: info: Reloading queue from file Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:16 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.247 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 2 Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::pushState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioPushState Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::setRepeat null single undefined Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::pushState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioPushState Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::setRandom null Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::pushState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioPushState Jun 13 22:51:16 volumio volumio[2575]: info: Setting Device type: Raspberry PI Jun 13 22:51:16 volumio volumio[2663]: Starting albumart workers Jun 13 22:51:16 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.178 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/137.0.0.0 Safari/537.36 Edg/137.0.0.0 Engine version: 3 Transport: polling Total Clients: 3 Jun 13 22:51:16 volumio volumio[2575]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Jun 13 22:51:16 volumio volumio[2575]: info: USB Boot Capable - System SBC Revision found in cpuinfo: e04171 Jun 13 22:51:16 volumio volumio[2575]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Jun 13 22:51:16 volumio volumio[2664]: Starting albumart workers Jun 13 22:51:16 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.247 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 4 Jun 13 22:51:16 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.178 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/137.0.0.0 Safari/537.36 Edg/137.0.0.0 Engine version: 3 Transport: polling Total Clients: 5 Jun 13 22:51:16 volumio volumio[2665]: Starting albumart workers Jun 13 22:51:16 volumio volumio-remote-updater[885]: [2025-06-13 22:51:16] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1749880274 101 Jun 13 22:51:16 volumio volumio[2575]: 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: 6 Jun 13 22:51:16 volumio volumio[2575]: info: Completed loading Core Plugins Jun 13 22:51:16 volumio volumio[2575]: info: Preparing to generate the ALSA configuration file Jun 13 22:51:16 volumio volumio[2575]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jun 13 22:51:16 volumio volumio[2575]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jun 13 22:51:16 volumio volumio[2575]: info: Reading ALSA contributions from plugins. Jun 13 22:51:16 volumio volumio[2575]: info: Asound.conf file written Jun 13 22:51:16 volumio sudo[2720]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Jun 13 22:51:16 volumio sudo[2720]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:16 volumio sudo[2720]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:16 volumio volumio[2575]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Jun 13 22:51:16 volumio volumio[2575]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Jun 13 22:51:16 volumio volumio[2575]: info: Output device has changed, restarting MPD Jun 13 22:51:16 volumio volumio[2575]: info: Output device has changed, restarting Shairport Sync Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:16 volumio sudo[2726]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 13 22:51:16 volumio sudo[2726]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:16 volumio sudo[2726]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:16 volumio sudo[2728]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 13 22:51:16 volumio volumio[2575]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 13 22:51:16 volumio sudo[2728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:16 volumio volumio[2575]: info: ___________ START PLUGINS ___________ Jun 13 22:51:16 volumio volumio[2575]: info: ControllerMpd::onStart: Initializing MPD Jun 13 22:51:16 volumio volumio[2575]: info: Creating MPD Configuration file Jun 13 22:51:16 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 13 22:51:16 volumio sudo[2736]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 13 22:51:16 volumio sudo[2736]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:16 volumio volumio[2575]: info: [1749880276455] CoreMusicLibrary::Adding element Media Servers Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:16 volumio sudo[2736]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:16 volumio sudo[2738]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 13 22:51:16 volumio sudo[2738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:16 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:16 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 13 22:51:16 volumio systemd[1]: mpd.service: Consumed 2.240s CPU time. Jun 13 22:51:16 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 13 22:51:16 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 13 22:51:16 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 13 22:51:16 volumio volumio[2575]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 13 22:51:16 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 13 22:51:16 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 13 22:51:16 volumio volumio[2575]: info: [1749880276524] CoreMusicLibrary::Adding element Last_100 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 13 22:51:16 volumio volumio[2575]: info: [1749880276526] CoreMusicLibrary::Adding element Webradio Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 13 22:51:16 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 13 22:51:16 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 13 22:51:16 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 13 22:51:16 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 13 22:51:16 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 13 22:51:16 volumio volumio[2575]: info: Initializing BBC Radios Jun 13 22:51:16 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 13 22:51:16 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: Creating Spotify config file Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio sudo[2767]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 13 22:51:16 volumio sudo[2767]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 13 22:51:16 volumio sudo[2767]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 13 22:51:16 volumio volumio[2575]: info: [1749880276682] CoreMusicLibrary::Adding element YouTube2 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:16 volumio volumio[2575]: Cannot find translation for source YouTube2 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 13 22:51:16 volumio volumio[2575]: info: [1749880276684] CoreMusicLibrary::Adding element YouTube Music Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:16 volumio volumio[2575]: Cannot find translation for source YouTube2 Jun 13 22:51:16 volumio volumio[2575]: Cannot find translation for source YouTube Music Jun 13 22:51:16 volumio volumio[2575]: info: SleepWakePlugin - onStart Jun 13 22:51:16 volumio volumio[2575]: info: SleepWakePlugin - Sleep scheduled in 7723313 milliseconds Jun 13 22:51:16 volumio volumio[2575]: info: SleepWakePlugin - Wake scheduled in 32923311 milliseconds Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jun 13 22:51:16 volumio volumio[2575]: info: Volumio Calling Home Jun 13 22:51:16 volumio volumio[2575]: info: Preparing to generate the ALSA configuration file Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: adding 91bfe525-62a7-46c0-b8b3-3e7578ed9240 Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Found device Volumio Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: this is already registered, 91bfe525-62a7-46c0-b8b3-3e7578ed9240 Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Found device Volumio Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jun 13 22:51:16 volumio volumio[2575]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jun 13 22:51:16 volumio volumio[2575]: info: Reading ALSA contributions from plugins. Jun 13 22:51:16 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.247 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Jun 13 22:51:16 volumio volumio[2575]: info: MPD Permissions set Jun 13 22:51:16 volumio volumio[2575]: info: MPD Permissions set Jun 13 22:51:16 volumio volumio[2575]: info: Spotify config file written Jun 13 22:51:16 volumio volumio[2575]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio sudo[2792]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 13 22:51:16 volumio sudo[2792]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jun 13 22:51:16 volumio systemd[1]: go-librespot-daemon.service: Killing process 2508 (go-librespot) with signal SIGKILL. Jun 13 22:51:16 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jun 13 22:51:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:16 volumio volumio[2575]: info: No need to fix Spotify hosts Jun 13 22:51:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 13 22:51:16 volumio go-librespot[2804]: go-librespot daemon starting... Jun 13 22:51:16 volumio volumio[2575]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jun 13 22:51:16 volumio sudo[2792]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:16 volumio go-librespot[2805]: time="2025-06-13T22:51:16-07:00" level=info msg="running go-librespot 0.2.0" Jun 13 22:51:16 volumio go-librespot[2805]: time="2025-06-13T22:51:16-07:00" level=debug msg="app state loaded" Jun 13 22:51:16 volumio go-librespot[2805]: time="2025-06-13T22:51:16-07:00" level=debug msg="stored credentials not found" Jun 13 22:51:16 volumio go-librespot[2805]: time="2025-06-13T22:51:16-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 13 22:51:16 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetVisibleSources Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetQueue Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::getQueue Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getQueue Jun 13 22:51:16 volumio volumio[2575]: info: Listing playlists Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 13 22:51:16 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetVisibleSources Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetQueue Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::getQueue Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getQueue Jun 13 22:51:16 volumio volumio[2575]: info: Listing playlists Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 13 22:51:16 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetVisibleSources Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetQueue Jun 13 22:51:16 volumio volumio[2575]: info: CoreStateMachine::getQueue Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getQueue Jun 13 22:51:16 volumio volumio[2575]: info: Listing playlists Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 13 22:51:16 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:16 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:16 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:16 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:17 volumio volumio[2575]: info: Starting Shairport Sync Jun 13 22:51:17 volumio volumio[2575]: info: Starting Shairport Sync Jun 13 22:51:17 volumio volumio[2575]: info: Starting Shairport Sync Jun 13 22:51:17 volumio sudo[2813]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 13 22:51:17 volumio sudo[2813]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:17 volumio sudo[2815]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 13 22:51:17 volumio sudo[2815]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:17 volumio sudo[2820]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 13 22:51:17 volumio sudo[2820]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:17 volumio go-librespot[2805]: time="2025-06-13T22:51:17-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 13 22:51:17 volumio go-librespot[2805]: time="2025-06-13T22:51:17-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 13 22:51:17 volumio go-librespot[2805]: time="2025-06-13T22:51:17-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 13 22:51:17 volumio go-librespot[2805]: time="2025-06-13T22:51:17-07:00" level=info msg="zeroconf server listening on port 37789" Jun 13 22:51:17 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 13 22:51:17 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 13 22:51:17 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 13 22:51:17 volumio systemd[1]: shairport-sync.service: Consumed 1.836s CPU time. Jun 13 22:51:17 volumio volumio[2575]: info: Asound.conf file unchanged, so no further update is needed Jun 13 22:51:17 volumio volumio[2575]: info: Output device has changed, restarting MPD Jun 13 22:51:17 volumio volumio[2575]: info: Output device has changed, restarting Shairport Sync Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:17 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 13 22:51:17 volumio sudo[2815]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:17 volumio sudo[2813]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:17 volumio sudo[2825]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 13 22:51:17 volumio sudo[2820]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:17 volumio sudo[2825]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:17 volumio sudo[2825]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:17 volumio sudo[2827]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 13 22:51:17 volumio sudo[2827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:17 volumio volumio[2575]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 13 22:51:17 volumio volumio[2575]: info: Volumio called home Jun 13 22:51:17 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 13 22:51:17 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 13 22:51:17 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 13 22:51:17 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 13 22:51:17 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 13 22:51:17 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 13 22:51:17 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 13 22:51:17 volumio volumio[2575]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jun 13 22:51:17 volumio sudo[2853]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 13 22:51:17 volumio sudo[2853]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 13 22:51:17 volumio sudo[2853]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:17 volumio volumio[2575]: info: MPD Permissions set Jun 13 22:51:17 volumio volumio[2575]: info: Shairport-Sync Started Jun 13 22:51:17 volumio volumio[2575]: Error adding Membership: Error: addMembership EINVAL Jun 13 22:51:17 volumio volumio[2575]: info: Shairport-Sync Started Jun 13 22:51:17 volumio volumio[2575]: info: Shairport-Sync Started Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:17 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:17 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:17 volumio volumio[2575]: info: Starting Shairport Sync Jun 13 22:51:17 volumio sudo[2862]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 13 22:51:17 volumio sudo[2862]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:17 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 13 22:51:17 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 13 22:51:17 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 13 22:51:17 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 13 22:51:17 volumio sudo[2862]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:17 volumio volumio[2575]: info: Shairport-Sync Started Jun 13 22:51:17 volumio mpd[2855]: 2025-06-13T22:51:17 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 13 22:51:17 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jun 13 22:51:17 volumio sudo[2728]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:17 volumio sudo[2827]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:17 volumio sudo[2738]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:17 volumio volumio[2575]: info: Completed starting Core Plugins Jun 13 22:51:17 volumio volumio[2575]: info: ------------------------------------------- Jun 13 22:51:17 volumio volumio[2575]: info: ----- MyVolumio plugins startup ---- Jun 13 22:51:17 volumio volumio[2575]: info: ------------------------------------------- Jun 13 22:51:17 volumio volumio[2575]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 13 22:51:17 volumio volumio[2575]: error: MPD error: The expression evaluated to a falsy value: Jun 13 22:51:17 volumio volumio[2575]: assert.ok(self.idling) Jun 13 22:51:17 volumio volumio[2575]: error: The expression evaluated to a falsy value: Jun 13 22:51:17 volumio volumio[2575]: assert.ok(self.idling) Jun 13 22:51:17 volumio volumio[2575]: error: MPD error: The expression evaluated to a falsy value: Jun 13 22:51:17 volumio volumio[2575]: assert.ok(self.idling) Jun 13 22:51:17 volumio volumio[2575]: error: The expression evaluated to a falsy value: Jun 13 22:51:17 volumio volumio[2575]: assert.ok(self.idling) Jun 13 22:51:17 volumio volumio[2575]: info: MPD running with PID2855 Jun 13 22:51:17 volumio volumio[2575]: ,establishing connection Jun 13 22:51:17 volumio volumio[2575]: error: updateQueue error: null Jun 13 22:51:17 volumio volumio[2575]: error: updateQueue error: null Jun 13 22:51:18 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.178 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/137.0.0.0 Safari/537.36 Edg/137.0.0.0 Engine version: 3 Transport: polling Total Clients: 10 Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:18 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:18 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:18 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:18 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:18 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::volumioGetVisibleSources Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:18 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:18 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 13 22:51:18 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:18 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:18 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:18 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:18 volumio volumio[2575]: info: Listing playlists Jun 13 22:51:18 volumio volumio[2575]: info: CoreCommandRouter::volumioGetQueue Jun 13 22:51:18 volumio volumio[2575]: info: CoreStateMachine::getQueue Jun 13 22:51:18 volumio volumio[2575]: info: CorePlayQueue::getQueue Jun 13 22:51:19 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:19 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:19 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:19 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:19 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:19 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:19 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254:3000 from 192.168.1.247 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 11 Jun 13 22:51:19 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:19 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:19 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 13 22:51:19 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 13 22:51:20 volumio volumio[2575]: info: go-librespot daemon successfully initialized Jun 13 22:51:23 volumio volumio[2575]: info: Initializing connection to go-librespot Websocket Jun 13 22:51:23 volumio go-librespot[2805]: time="2025-06-13T22:51:23-07:00" level=debug msg="new websocket client" Jun 13 22:51:23 volumio volumio[2575]: info: Connection to go-librespot Websocket established Jun 13 22:51:23 volumio sudo[2901]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 13 22:51:23 volumio sudo[2901]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:23 volumio sudo[2901]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:23 volumio sudo[2903]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 13 22:51:23 volumio sudo[2903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:23 volumio sudo[2903]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:23 volumio sudo[2907]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 13 22:51:23 volumio sudo[2907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:23 volumio sudo[2907]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:23 volumio volumio[2575]: info: Upmpdcli Daemon Started Jun 13 22:51:25 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 13 22:51:25 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:25 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:25 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:25 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:25 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:25 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:26 volumio volumio[2575]: info: Getting Spotify volume Jun 13 22:51:26 volumio volumio[2575]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Jun 13 22:51:26 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:26 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:26 volumio volumio[2575]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 13 22:51:26 volumio volumio[2575]: SPOTIFY: SPOTIFY VOLUME undefined Jun 13 22:51:26 volumio volumio[2575]: SPOTIFY: VOLUMIO VOLUME 100 Jun 13 22:51:26 volumio volumio[2575]: info: Aligning Spotify Volume to Volumio Volume Jun 13 22:51:26 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:26 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:26 volumio volumio[2575]: info: Setting Spotify Volume from Volumio: 100 Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 13 22:51:26 volumio volumio[2575]: info: Adding plugin bluetooth to MyMusic Plugins Jun 13 22:51:26 volumio volumio[2575]: info: Adding plugin multiroom to MyMusic Plugins Jun 13 22:51:26 volumio volumio[2575]: info: Adding plugin metavolumio to MyMusic Plugins Jun 13 22:51:26 volumio volumio[2575]: info: Adding plugin cd_controller to MyMusic Plugins Jun 13 22:51:26 volumio volumio[2575]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 13 22:51:26 volumio volumio[2575]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 13 22:51:26 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:26 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:26 volumio volumio[2575]: info: Starting MyVolumio Remote Streaming Endpoints Jun 13 22:51:26 volumio volumio[2575]: info: MyVolumio login type: Token Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 13 22:51:26 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 13 22:51:27 volumio volumio[2575]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 13 22:51:27 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 13 22:51:27 volumio volumio[2575]: info: Streaming services startup Jun 13 22:51:27 volumio volumio[2575]: info: Starting Streaming Daemon Jun 13 22:51:27 volumio sudo[2910]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 13 22:51:27 volumio sudo[2910]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:27 volumio volumio[2575]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 13 22:51:27 volumio sudo[2910]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:27 volumio volumio[2575]: error: Cannot start Volumio Streaming Daemon Jun 13 22:51:27 volumio volumio[2575]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 13 22:51:27 volumio volumio[2575]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 13 22:51:27 volumio sudo[2917]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 13 22:51:27 volumio sudo[2917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:27 volumio sudo[2917]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:27 volumio sudo[2919]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 13 22:51:27 volumio sudo[2919]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:27 volumio sudo[2919]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:27 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.247 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 13 Jun 13 22:51:27 volumio sudo[2923]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 13 22:51:27 volumio sudo[2923]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:27 volumio sudo[2923]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:27 volumio sudo[2925]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 13 22:51:27 volumio sudo[2925]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:27 volumio sudo[2925]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:27 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.247 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 13 Jun 13 22:51:27 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:27 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:27 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetVisibleSources Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetQueue Jun 13 22:51:27 volumio volumio[2575]: info: CoreStateMachine::getQueue Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getQueue Jun 13 22:51:27 volumio volumio[2575]: info: Listing playlists Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 13 22:51:27 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:27 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:27 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:27 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:27 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetVisibleSources Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetQueue Jun 13 22:51:27 volumio volumio[2575]: info: CoreStateMachine::getQueue Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getQueue Jun 13 22:51:27 volumio volumio[2575]: info: Listing playlists Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 13 22:51:27 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:27 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:27 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:27 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 13 22:51:27 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 13 22:51:27 volumio volumio[2575]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jun 13 22:51:27 volumio volumio[2575]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Jun 13 22:51:27 volumio volumio[2575]: info: Sending Spotify command with payload to local API: /player/volume Jun 13 22:51:27 volumio volumio[2575]: error: Failed to send command to Spotify local API: /player/volume: Error: Bad Request Jun 13 22:51:28 volumio volumio[2575]: info: MyVolumio token set successfully Jun 13 22:51:28 volumio volumio[2575]: info: MYVOLUMIO: Adding device Jun 13 22:51:28 volumio volumio[2575]: info: MYVOLUMIO: Evaluating Server Jun 13 22:51:28 volumio volumio[2575]: info: MyVolumio Plan changed: premium Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Jun 13 22:51:28 volumio volumio[2575]: info: Removing browser output: myVolumio user plan is not superstar Jun 13 22:51:28 volumio volumio[2575]: info: Removing audio output: Jun 13 22:51:28 volumio volumio[2575]: info: MYVOLUMIO: Adding device Jun 13 22:51:28 volumio volumio[2575]: info: MYVOLUMIO: Evaluating Server Jun 13 22:51:28 volumio volumio[2575]: info: Remote config written successfully Jun 13 22:51:28 volumio volumio[2575]: info: Starting Tunnel 1 Jun 13 22:51:28 volumio volumio[2575]: info: Starting Tunnel Connection Checker Jun 13 22:51:28 volumio volumio[2575]: info: Completed starting MyVolumio Plugin Jun 13 22:51:28 volumio volumio[2575]: info: MYVolumio Device enabled Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Jun 13 22:51:28 volumio volumio[2575]: info: MyVolumio status changed Jun 13 22:51:28 volumio volumio[2575]: info: Streaming services startup Jun 13 22:51:28 volumio volumio[2575]: info: Starting Streaming Daemon Jun 13 22:51:28 volumio sudo[2961]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 13 22:51:28 volumio sudo[2961]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:28 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Plugin music_service/qobuzconnect is enabled for this plan, but could not be found on the local filesystem! Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Jun 13 22:51:28 volumio sudo[2961]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:28 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Jun 13 22:51:28 volumio sudo[2965]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Jun 13 22:51:28 volumio sudo[2965]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:28 volumio sudo[2965]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:28 volumio volumio[2575]: /usr/bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Jun 13 22:51:28 volumio volumio[2575]: info: MRS: MultiRoom plugin initialized Jun 13 22:51:28 volumio volumio[2575]: info: MRS: STOPPING SNAPCLIENT Jun 13 22:51:28 volumio volumio[2575]: info: MRS: Snap server stop Jun 13 22:51:28 volumio volumio[2575]: info: MRS: STOPPING volumioStreaming Jun 13 22:51:28 volumio sudo[2982]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Jun 13 22:51:28 volumio sudo[2982]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:28 volumio sudo[2985]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Jun 13 22:51:28 volumio sudo[2985]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Jun 13 22:51:28 volumio sudo[2990]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jun 13 22:51:28 volumio sudo[2987]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Jun 13 22:51:28 volumio sudo[2987]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:28 volumio sudo[2990]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:28 volumio sudo[2990]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Jun 13 22:51:28 volumio sudo[2982]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:28 volumio sudo[2985]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:28 volumio sudo[2987]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:28 volumio volumio[2575]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Jun 13 22:51:28 volumio volumio[2575]: info: Preparing to generate the ALSA configuration file Jun 13 22:51:29 volumio volumio[2575]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jun 13 22:51:29 volumio volumio[2575]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Jun 13 22:51:29 volumio volumio[2575]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jun 13 22:51:29 volumio volumio[2575]: info: Reading ALSA contributions from plugins. Jun 13 22:51:29 volumio volumio[2575]: info: Setting Geolocation for MyVolumio to us2 Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: Setting Geolocation for MyVolumio to us2 Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: MRS: Removed streaming files Jun 13 22:51:29 volumio volumio[2575]: info: MRS: volumioStreaming STOPPED Jun 13 22:51:29 volumio volumio[2575]: info: MRS: SNAPSERVER STOPPED Jun 13 22:51:29 volumio volumio[2575]: info: MRS: SNAPCLIENT STOPPED Jun 13 22:51:29 volumio volumio[2575]: error: Cannot start Volumio Streaming Daemon Jun 13 22:51:29 volumio volumio[2575]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 13 22:51:29 volumio volumio[2575]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 13 22:51:29 volumio volumio[2575]: info: Asound.conf file written Jun 13 22:51:29 volumio sudo[2996]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Jun 13 22:51:29 volumio sudo[2996]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:29 volumio sudo[2996]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:29 volumio volumio[2575]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Jun 13 22:51:29 volumio volumio[2575]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Jun 13 22:51:29 volumio volumio[2575]: info: Output device has changed, restarting MPD Jun 13 22:51:29 volumio volumio[2575]: info: Output device has changed, restarting Shairport Sync Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:29 volumio sudo[3002]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 13 22:51:29 volumio sudo[3002]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:29 volumio sudo[3002]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:29 volumio sudo[3004]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 13 22:51:29 volumio sudo[3004]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:29 volumio volumio[2575]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 13 22:51:29 volumio volumio[2575]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Jun 13 22:51:29 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] onStart Jun 13 22:51:29 volumio volumio[2575]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Jun 13 22:51:29 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jun 13 22:51:29 volumio volumio[2575]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Jun 13 22:51:29 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Jun 13 22:51:29 volumio volumio[2575]: info: MRS: Pushing multiroomSync output for this device Jun 13 22:51:29 volumio volumio[2575]: info: MRS: Pushing multiroomSync output Jun 13 22:51:29 volumio volumio[2575]: info: Adding audio output: Jun 13 22:51:29 volumio volumio[2575]: info: Adding audio output: Jun 13 22:51:29 volumio volumio[2575]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 13 22:51:29 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 13 22:51:29 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 13 22:51:29 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 13 22:51:29 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Jun 13 22:51:29 volumio volumio[2575]: info: Adding METAVOLUMIO REST API Endpoints Jun 13 22:51:29 volumio volumio[2575]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Jun 13 22:51:29 volumio volumio[2575]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Jun 13 22:51:29 volumio volumio[2575]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Jun 13 22:51:29 volumio volumio[2575]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Jun 13 22:51:29 volumio volumio[2575]: info: Preparing CD Folders Jun 13 22:51:29 volumio volumio[2575]: info: Adding CD REST API Endpoints Jun 13 22:51:29 volumio volumio[2575]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Jun 13 22:51:29 volumio volumio[2575]: info: Starting UDEV Watcher for CD Jun 13 22:51:29 volumio volumio[2575]: info: Detecting CD presence with UDEV Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Jun 13 22:51:29 volumio bluetoothd[851]: Adv Monitor app :1.51 disconnected from D-Bus Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Jun 13 22:51:29 volumio volumio[2575]: info: Adding inputs REST Endpoints Jun 13 22:51:29 volumio volumio[2575]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Jun 13 22:51:29 volumio volumio[2575]: info: Scanning Audio Inputs Jun 13 22:51:29 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 13 22:51:29 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 13 22:51:29 volumio volumio[2575]: info: Checking against Known Cards name Jun 13 22:51:29 volumio volumio[2575]: info: Adding Server instance for streaming Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Jun 13 22:51:29 volumio volumio[2575]: error: Hi Res Audio Failed Login: Missing Login Data Jun 13 22:51:29 volumio volumio[2575]: info: Adding HIGHRESAUDIO REST API Endpoints Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Jun 13 22:51:29 volumio volumio[2575]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Jun 13 22:51:29 volumio sudo[3024]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Jun 13 22:51:29 volumio sudo[3024]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:29 volumio volumio[2575]: info: Stopping AccessToken refresher cron Jun 13 22:51:29 volumio sudo[3024]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:29 volumio volumio[2575]: info: AccessToken refresher cron started Jun 13 22:51:29 volumio volumio[2575]: info: Stopping AccessToken refresher cron for QOBUZ Jun 13 22:51:29 volumio volumio[2575]: info: AccessToken refresher cron started for QOBUZ Jun 13 22:51:29 volumio volumio[2575]: info: Adding TIDAL REST API Endpoints Jun 13 22:51:29 volumio volumio[2575]: info: Adding QOBUZ REST API Endpoints Jun 13 22:51:29 volumio sudo[3022]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 13 22:51:29 volumio sudo[3022]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 13 22:51:29 volumio sudo[3022]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:29 volumio volumio[2575]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Jun 13 22:51:29 volumio volumio[2575]: info: MPD Permissions set Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio sudo[3030]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Jun 13 22:51:29 volumio sudo[3030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:29 volumio volumio[2575]: info: Starting Shairport Sync Jun 13 22:51:29 volumio sudo[3030]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:29 volumio volumio[2575]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::volumioStop Jun 13 22:51:29 volumio volumio[2575]: info: CoreStateMachine::stop Jun 13 22:51:29 volumio volumio[2575]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 13 22:51:29 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Jun 13 22:51:29 volumio volumio[2575]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 13 22:51:29 volumio sudo[3039]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 13 22:51:29 volumio sudo[3039]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 13 22:51:29 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:29 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:29 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 13 22:51:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 13 22:51:29 volumio systemd[1]: shairport-sync.service: Consumed 1.538s CPU time. Jun 13 22:51:29 volumio volumio[2575]: info: Successfully Added MyVolumio device Jun 13 22:51:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 13 22:51:29 volumio sudo[3039]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:29 volumio volumio[2575]: info: Shairport-Sync Started Jun 13 22:51:29 volumio volumio[2575]: info: MRS: Found cast device: Chromecast-19f32a9dc6ae3b0c029c808824208618 Jun 13 22:51:29 volumio volumio[2575]: info: Adding audio output: Jun 13 22:51:29 volumio volumio[2575]: info: Successfully Added MyVolumio device Jun 13 22:51:29 volumio mpd[3028]: 2025-06-13T22:51:29 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 13 22:51:29 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jun 13 22:51:29 volumio sudo[3004]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:29 volumio volumio[2575]: error: updateQueue error: null Jun 13 22:51:30 volumio volumio[2575]: info: Updating MyVolumio device info Jun 13 22:51:30 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:30 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:30 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:30 volumio volumio[2575]: info: Updating MyVolumio device info Jun 13 22:51:30 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:30 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:30 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:30 volumio volumio[2575]: info: Successfully Updated MyVolumio device Jun 13 22:51:30 volumio volumio[2575]: info: Successfully Updated MyVolumio device Jun 13 22:51:32 volumio volumio[2575]: info: TidalConnect service stoped! Jun 13 22:51:32 volumio volumio[2575]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Jun 13 22:51:32 volumio volumio[2575]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Jun 13 22:51:32 volumio sudo[3081]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Jun 13 22:51:32 volumio sudo[3081]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:32 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:32 volumio vtcs[3084]: /usr/bin/vtcs: error while loading shared libraries: libssl.so.1.1: cannot open shared object file: No such file or directory Jun 13 22:51:32 volumio sudo[3081]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:32 volumio systemd[1]: vtcs.service: Main process exited, code=exited, status=127/n/a Jun 13 22:51:32 volumio systemd[1]: vtcs.service: Failed with result 'exit-code'. Jun 13 22:51:32 volumio sudo[3087]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 13 22:51:32 volumio sudo[3087]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:32 volumio sudo[3087]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:32 volumio sudo[3089]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 13 22:51:32 volumio sudo[3089]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:32 volumio sudo[3089]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:32 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.247 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 13 Jun 13 22:51:32 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:32 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:32 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetVisibleSources Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetQueue Jun 13 22:51:32 volumio volumio[2575]: info: CoreStateMachine::getQueue Jun 13 22:51:32 volumio volumio[2575]: info: CorePlayQueue::getQueue Jun 13 22:51:32 volumio volumio[2575]: info: Listing playlists Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 13 22:51:32 volumio volumio[2575]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jun 13 22:51:32 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:32 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:32 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: Received Get System Info Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:32 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:32 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 13 22:51:32 volumio systemd[1]: vtcs.service: Scheduled restart job, restart counter is at 1. Jun 13 22:51:32 volumio systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:32 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:32 volumio vtcs[3093]: /usr/bin/vtcs: error while loading shared libraries: libssl.so.1.1: cannot open shared object file: No such file or directory Jun 13 22:51:32 volumio systemd[1]: vtcs.service: Main process exited, code=exited, status=127/n/a Jun 13 22:51:32 volumio systemd[1]: vtcs.service: Failed with result 'exit-code'. Jun 13 22:51:32 volumio systemd[1]: vtcs.service: Scheduled restart job, restart counter is at 2. Jun 13 22:51:32 volumio systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:32 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:32 volumio vtcs[3095]: /usr/bin/vtcs: error while loading shared libraries: libssl.so.1.1: cannot open shared object file: No such file or directory Jun 13 22:51:32 volumio systemd[1]: vtcs.service: Main process exited, code=exited, status=127/n/a Jun 13 22:51:32 volumio systemd[1]: vtcs.service: Failed with result 'exit-code'. Jun 13 22:51:33 volumio systemd[1]: vtcs.service: Scheduled restart job, restart counter is at 3. Jun 13 22:51:33 volumio systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:33 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:33 volumio vtcs[3097]: /usr/bin/vtcs: error while loading shared libraries: libssl.so.1.1: cannot open shared object file: No such file or directory Jun 13 22:51:33 volumio systemd[1]: vtcs.service: Main process exited, code=exited, status=127/n/a Jun 13 22:51:33 volumio systemd[1]: vtcs.service: Failed with result 'exit-code'. Jun 13 22:51:33 volumio systemd[1]: vtcs.service: Scheduled restart job, restart counter is at 4. Jun 13 22:51:33 volumio systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:33 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:33 volumio vtcs[3099]: /usr/bin/vtcs: error while loading shared libraries: libssl.so.1.1: cannot open shared object file: No such file or directory Jun 13 22:51:33 volumio systemd[1]: vtcs.service: Main process exited, code=exited, status=127/n/a Jun 13 22:51:33 volumio systemd[1]: vtcs.service: Failed with result 'exit-code'. Jun 13 22:51:33 volumio sudo[3107]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Jun 13 22:51:33 volumio sudo[3107]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:51:33 volumio systemd[1]: vtcs.service: Scheduled restart job, restart counter is at 5. Jun 13 22:51:33 volumio systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:33 volumio systemd[1]: vtcs.service: Start request repeated too quickly. Jun 13 22:51:33 volumio systemd[1]: vtcs.service: Failed with result 'exit-code'. Jun 13 22:51:33 volumio systemd[1]: Failed to start vtcs.service - Volumio Tidal Connect Service. Jun 13 22:51:33 volumio autossh[1850]: received signal to exit (15) Jun 13 22:51:33 volumio systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Jun 13 22:51:33 volumio systemd[1]: sshtunnel.service: Deactivated successfully. Jun 13 22:51:33 volumio systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Jun 13 22:51:33 volumio systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Jun 13 22:51:33 volumio sudo[3107]: pam_unix(sudo:session): session closed for user root Jun 13 22:51:33 volumio volumio[2575]: info: Remote SSH Started Jun 13 22:51:33 volumio autossh[3110]: port set to 0, monitoring disabled Jun 13 22:51:33 volumio autossh[3110]: starting ssh (count 1) Jun 13 22:51:33 volumio autossh[3110]: ssh child pid is 3113 Jun 13 22:51:33 volumio volumio[2575]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jun 13 22:51:33 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:33 volumio volumio[2575]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.fDhlBCgtuWZa2kVzrNQNsqYHDbX2.4259593a93de721636e93db15c6ff6b8.state.status' Jun 13 22:51:33 volumio volumiossh-tunnel[3113]: Warning: Permanently added '[us2.myvolumio.org]:2222' (RSA) to the list of known hosts. Jun 13 22:51:34 volumio volumio[2575]: info: MRS: Getting audio outputs on start Jun 13 22:51:34 volumio volumio[2575]: info: MRS: Requesting all other devices output Jun 13 22:51:35 volumio volumio[2575]: info: TidalConnect service started! Jun 13 22:51:35 volumio volumio[2575]: [Metrics] CommandRouter: 24s 643.05ms Jun 13 22:51:35 volumio volumio[2575]: info: CoreCommandRouter::volumiosetStartupVolume Jun 13 22:51:35 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:35 volumio volumio[2575]: info: VolumeController:: Setting startup Volume 20 Jun 13 22:51:35 volumio volumio[2575]: info: VolumeController::SetAlsaVolume20 Jun 13 22:51:35 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [VOLUME HOOK] Intercepted volume 20 - forwarding to Bluetooth device Jun 13 22:51:35 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [VOLUME HOOK] Intercepted volume 20 - forwarding to Bluetooth device Jun 13 22:51:35 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [DEBUG] self.currentMAC = undefined Jun 13 22:51:35 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [DEBUG] transportManager.currentMAC = undefined Jun 13 22:51:35 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [DEBUG] MAC resolved for push = undefined Jun 13 22:51:35 volumio volumio[2575]: ------------------------------------ BT MESSAGE: pushVolumeToDevice: Invalid or unknown MAC address Jun 13 22:51:35 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:35 volumio volumio[2575]: info: CoreCommandRouter::Close All Modals sent Jun 13 22:51:35 volumio volumio[2575]: info: CoreCommandRouter::Close All Modals sent Jun 13 22:51:35 volumio volumio[2575]: info: CoreStateMachine::pushState Jun 13 22:51:35 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 22:51:35 volumio volumio[2575]: info: CoreCommandRouter::volumioPushState Jun 13 22:51:35 volumio volumio[2575]: info: MRS: Pushing multiroomSync output update for this device Jun 13 22:51:35 volumio volumio[2575]: info: MRS: Pushing multiroomSync output Jun 13 22:51:35 volumio volumio[2575]: error: Help! Some callbacks for volumioPushState are crashing! Jun 13 22:51:35 volumio volumio[2575]: error: Cannot read properties of undefined (reading 'sendVolumeMute') Jun 13 22:51:35 volumio volumio[2575]: info: PeppySpectrum ---peppyspectrum status Jun 13 22:51:35 volumio volumio[2575]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Jun 13 22:51:35 volumio volumio[2575]: SPOTIFY: SPOTIFY VOLUME 100 Jun 13 22:51:35 volumio volumio[2575]: SPOTIFY: VOLUMIO VOLUME 20 Jun 13 22:51:35 volumio volumio[2575]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 13 22:51:35 volumio volumio[2575]: info: Setting Spotify Volume from Volumio: 20 Jun 13 22:51:36 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 13 22:51:36 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 13 22:51:36 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jun 13 22:51:36 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 13 22:51:36 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jun 13 22:51:36 volumio volumio[2575]: SPOTIFY: SETTING SPOTIFY VOLUME 20 Jun 13 22:51:36 volumio volumio[2575]: info: Sending Spotify command with payload to local API: /player/volume Jun 13 22:51:37 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 13 22:51:37 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 13 22:51:37 volumio volumio[2575]: info: Executing endpoint metavolumio Jun 13 22:51:37 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 13 22:51:38 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Jun 13 22:51:39 volumio volumio[2575]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 13 22:51:41 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 13 22:51:41 volumio volumio[2575]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 14 Jun 13 22:51:41 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:42 volumio volumio[2575]: info: BOOT COMPLETED Jun 13 22:51:42 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 13 22:51:46 volumio volumio-remote-updater[885]: Test mode disabled Jun 13 22:51:46 volumio volumio-remote-updater[885]: Alpha mode disabled Jun 13 22:51:46 volumio volumio-remote-updater[885]: Alpha legacy test mode disabled Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::volumioGetBrowseSources Jun 13 22:51:46 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 13 22:51:47 volumio volumio[2575]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jun 13 22:51:47 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jun 13 22:51:55 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:51:55 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:51:55 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:51:55 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:51:55 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:52:20 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jun 13 22:52:20 volumio dbus-daemon[855]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.56' (uid=0 pid=3189 comm="timedatectl show --property=NTPSynchronized --valu") Jun 13 22:52:20 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jun 13 22:52:20 volumio dbus-daemon[855]: [system] Successfully activated service 'org.freedesktop.timedate1' Jun 13 22:52:20 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Jun 13 22:52:20 volumio setdatetime-helper.sh[3188]: Time is not synchronized. Attempting to sync... Jun 13 22:52:20 volumio sudo[3197]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Sat, 14 Jun 2025 05:52:21 GMT#015' Jun 13 22:52:20 volumio sudo[3197]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 13 22:52:21 volumio setdatetime-helper.sh[3198]: Fri Jun 13 22:52:21 PDT 2025 Jun 13 22:52:21 volumio sudo[3197]: pam_unix(sudo:session): session closed for user root Jun 13 22:52:21 volumio setdatetime-helper.sh[3188]: Time synchronized successfully. Jun 13 22:52:21 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jun 13 22:52:21 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jun 13 22:52:23 volumio volumio[2575]: info: Received OAUTH Data Jun 13 22:52:23 volumio volumio[2575]: info: Executing Spotify Oauth Login Jun 13 22:52:23 volumio volumio[2575]: info: Saving Spotify Refresh Token Jun 13 22:52:23 volumio sudo[3216]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 13 22:52:23 volumio sudo[3216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:52:23 volumio sudo[3216]: pam_unix(sudo:session): session closed for user root Jun 13 22:52:23 volumio sudo[3218]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 13 22:52:23 volumio sudo[3218]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:52:23 volumio sudo[3218]: pam_unix(sudo:session): session closed for user root Jun 13 22:52:24 volumio volumio[2575]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.247 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 14 Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::volumioGetVisibleSources Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 13 22:52:24 volumio volumio[2575]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jun 13 22:52:24 volumio volumio[2575]: info: Received Get System Info Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:52:24 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:24 volumio volumio[2575]: info: Listing playlists Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 13 22:52:24 volumio volumio[2575]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 13 22:52:24 volumio volumio[2575]: SPOTIFY: BQBNGNKZaWJaI4nT6kj5u6SgBbuvFIQpGYixFQH986cSdlJbp7J2feERjViwdyN6-ZDzmYRR6VyrDdzf5q1RPC23BJGGT3CYhJhbtj1KsqfU8drAUZP09dZ8twc1qMbg3i8nBvXvE3Aii_xg_W8Fgaw5Tbr5JJniCJC0T-MJVejRUP-CjQwHFU3NLMlfm9VaaTqi0FHQ_4mRjW2BJzQhqDYF7F0Z5wZTn36wHyfpswcOCazhjA9UllhFN2jRBim1d_YekXMiwHBK36ZqTKGvIT2nZOohyQ15v7qoYu-6kY-XFs8 Jun 13 22:52:24 volumio volumio[2575]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 13 22:52:24 volumio volumio[2575]: info: New Spotify access token = BQBNGNKZaWJaI4nT6kj5u6SgBbuvFIQpGYixFQH986cSdlJbp7J2feERjViwdyN6-ZDzmYRR6VyrDdzf5q1RPC23BJGGT3CYhJhbtj1KsqfU8drAUZP09dZ8twc1qMbg3i8nBvXvE3Aii_xg_W8Fgaw5Tbr5JJniCJC0T-MJVejRUP-CjQwHFU3NLMlfm9VaaTqi0FHQ_4mRjW2BJzQhqDYF7F0Z5wZTn36wHyfpswcOCazhjA9UllhFN2jRBim1d_YekXMiwHBK36ZqTKGvIT2nZOohyQ15v7qoYu-6kY-XFs8 Jun 13 22:52:24 volumio volumio[2575]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 13 22:52:24 volumio volumio[2575]: SPOTIFY: User informations: {"country":"US","display_name":"22wbf3d2bwtkml5jrta5crf2a","email":"sonnythaitran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/22wbf3d2bwtkml5jrta5crf2a"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/22wbf3d2bwtkml5jrta5crf2a","id":"22wbf3d2bwtkml5jrta5crf2a","images":[],"product":"premium","type":"user","uri":"spotify:user:22wbf3d2bwtkml5jrta5crf2a"} Jun 13 22:52:24 volumio volumio[2575]: info: Creating Spotify config file Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 13 22:52:24 volumio volumio[2575]: info: Spotify config file written Jun 13 22:52:24 volumio sudo[3224]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 13 22:52:24 volumio sudo[3224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:52:24 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jun 13 22:52:24 volumio systemd[1]: go-librespot-daemon.service: Killing process 2809 (go-librespot) with signal SIGKILL. Jun 13 22:52:24 volumio volumio[2575]: info: Connection to go-librespot Websocket closed Jun 13 22:52:24 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jun 13 22:52:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 13 22:52:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 13 22:52:24 volumio go-librespot[3226]: go-librespot daemon starting... Jun 13 22:52:24 volumio sudo[3224]: pam_unix(sudo:session): session closed for user root Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=info msg="running go-librespot 0.2.0" Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=debug msg="app state loaded" Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=debug msg="stored credentials not found" Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 13 22:52:24 volumio volumio[2575]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 13 22:52:24 volumio volumio[2575]: SPOTIFY: BQBXq5yJG-nxdfH52rhaoee6HodBT3xI34V_W_sc69ozkvJw-K-GAv7YdX8FdzbPxYHaaIPEQy9RBg67BnFGzx1ltjHbWfP8d74_CVNxUDPPAAJmJ5B4A77kwBWySQxj8j3klC3_572uQTDAntZiCB6S4R3Q95vdWqVAajvB9ZJVgPheSdedVLscwp-w_rpzdg7AV5zXrI04WkCwhXdAEHCHp8cRIfhBRCtktor3BhJ9T1EussHgpMPYmp8NYrE7OaVH8Eo_QMIKgpWEhRVfiDN-p1H_2KOqGtFH6d3nJEeYcRc Jun 13 22:52:24 volumio volumio[2575]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 13 22:52:24 volumio volumio[2575]: info: New Spotify access token = BQBXq5yJG-nxdfH52rhaoee6HodBT3xI34V_W_sc69ozkvJw-K-GAv7YdX8FdzbPxYHaaIPEQy9RBg67BnFGzx1ltjHbWfP8d74_CVNxUDPPAAJmJ5B4A77kwBWySQxj8j3klC3_572uQTDAntZiCB6S4R3Q95vdWqVAajvB9ZJVgPheSdedVLscwp-w_rpzdg7AV5zXrI04WkCwhXdAEHCHp8cRIfhBRCtktor3BhJ9T1EussHgpMPYmp8NYrE7OaVH8Eo_QMIKgpWEhRVfiDN-p1H_2KOqGtFH6d3nJEeYcRc Jun 13 22:52:24 volumio volumio[2575]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=info msg="zeroconf server listening on port 40265" Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=debug msg="obtained new client token: AABRQz4O0m7VrBVTILHCD0YGWJEa6Z/w6I2mIDT+83/UN6t6YH3PI217CE95sWVZotU4GnsLFY4R7vKBr4LW/cF8eSOKQ/fNTaYWAkH+y8+BcTn25SVS/0x5nNpoXC0hFH0S1w1T56uNPgQ6sXijCdoRO9RpqhVaLKB9r8Af/8rhS1LuA2ygm9alIuxAkVwS4rj37akbfwXsmkgKYg1ZI2INl24xcWVNMY2729qHF0ZRdmpQJcetQGGX" Jun 13 22:52:24 volumio volumio[2575]: SPOTIFY: User informations: {"country":"US","display_name":"22wbf3d2bwtkml5jrta5crf2a","email":"sonnythaitran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/22wbf3d2bwtkml5jrta5crf2a"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/22wbf3d2bwtkml5jrta5crf2a","id":"22wbf3d2bwtkml5jrta5crf2a","images":[],"product":"premium","type":"user","uri":"spotify:user:22wbf3d2bwtkml5jrta5crf2a"} Jun 13 22:52:24 volumio volumio[2575]: info: Spotify Successfully logged in Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 13 22:52:24 volumio volumio[2575]: info: [1749880344823] CoreMusicLibrary::Adding element Spotify Jun 13 22:52:24 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:52:24 volumio volumio[2575]: Cannot find translation for source YouTube2 Jun 13 22:52:24 volumio volumio[2575]: Cannot find translation for source YouTube Music Jun 13 22:52:24 volumio volumio[2575]: Cannot find translation for source Spotify Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=debug msg="completed keyexchange" Jun 13 22:52:24 volumio go-librespot[3227]: time="2025-06-13T22:52:24-07:00" level=debug msg="completed challenge" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=info msg="authenticated AP as 22wbf3d2bwtkml5jrta5crf2a" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=info msg="authenticated Login5 as 22wbf3d2bwtkml5jrta5crf2a" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="stored credentials for 22wbf3d2bwtkml5jrta5crf2a" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="initializing zeroconf session, username: 22wbf3d2bwtkml5jrta5crf2a" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="dealer connection opened" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=trace msg="starting accesspoint recv loop" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=trace msg="starting dealer recv loop" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=trace msg="received accesspoint ping" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="received connection id: NmFiYTQ2Y2YtNzNhNy00NjkzLTk2YjgtNzNjZDcyYWVhZmRmK2RlYWxlcit0Y3A6Ly8wYWNiZDgyZS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArREYzOTVBQ0VCOTkyQzhGRjVCRjQ2MzkxNEYxM0JFQkE2NTE4Q0M2NDZEODc0RTlFODEzMDVDQUQ3QjQ3NjkwNA==" Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=trace msg="received accesspoint pong ack" Jun 13 22:52:25 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jun 13 22:52:25 volumio go-librespot[3227]: time="2025-06-13T22:52:25-07:00" level=debug msg="put connect state because NEW_DEVICE" Jun 13 22:52:25 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 13 22:52:25 volumio volumio[2575]: info: Received Get System Info Jun 13 22:52:25 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:52:25 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:52:25 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:52:25 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:25 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:52:26 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:52:26 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:52:26 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:52:26 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:26 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:52:26 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 13 22:52:26 volumio volumio[2575]: info: Received Get System Info Jun 13 22:52:26 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:52:26 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:52:26 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:52:26 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:26 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:52:27 volumio volumio[2575]: info: Initializing connection to go-librespot Websocket Jun 13 22:52:27 volumio go-librespot[3227]: time="2025-06-13T22:52:27-07:00" level=debug msg="new websocket client" Jun 13 22:52:27 volumio volumio[2575]: info: Connection to go-librespot Websocket established Jun 13 22:52:27 volumio volumio[2575]: info: go-librespot daemon successfully initialized Jun 13 22:52:28 volumio volumio[2575]: info: CoreCommandRouter::volumioVolatilePlay Jun 13 22:52:28 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] play Jun 13 22:52:28 volumio volumio[2575]: ------------------------------------ BT MESSAGE: sendPlay skipped: activePlayer not bound or invalid Jun 13 22:52:29 volumio volumio[2575]: info: CoreCommandRouter::volumioVolatilePlay Jun 13 22:52:29 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] play Jun 13 22:52:29 volumio volumio[2575]: ------------------------------------ BT MESSAGE: sendPlay skipped: activePlayer not bound or invalid Jun 13 22:52:30 volumio volumio[2575]: info: Getting Spotify volume Jun 13 22:52:30 volumio volumio[2575]: info: Spotify volume: 100 Jun 13 22:52:30 volumio volumio[2575]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 Jun 13 22:52:30 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:30 volumio volumio[2575]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Jun 13 22:52:30 volumio volumio[2575]: SPOTIFY: SPOTIFY VOLUME 100 Jun 13 22:52:30 volumio volumio[2575]: SPOTIFY: VOLUMIO VOLUME 20 Jun 13 22:52:30 volumio volumio[2575]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 13 22:52:30 volumio volumio[2575]: info: Setting Spotify Volume from Volumio: 20 Jun 13 22:52:30 volumio volumio[2575]: info: Initializing connection to go-librespot Websocket Jun 13 22:52:30 volumio go-librespot[3227]: time="2025-06-13T22:52:30-07:00" level=debug msg="new websocket client" Jun 13 22:52:30 volumio volumio[2575]: info: Connection to go-librespot Websocket established Jun 13 22:52:31 volumio volumio[2575]: SPOTIFY: SETTING SPOTIFY VOLUME 20 Jun 13 22:52:31 volumio volumio[2575]: info: Sending Spotify command with payload to local API: /player/volume Jun 13 22:52:31 volumio go-librespot[3227]: time="2025-06-13T22:52:31-07:00" level=debug msg="update volume to 13107/65535" Jun 13 22:52:32 volumio volumio[2575]: info: CoreCommandRouter::volumioGetQueue Jun 13 22:52:32 volumio volumio[2575]: info: CoreStateMachine::getQueue Jun 13 22:52:32 volumio volumio[2575]: info: CorePlayQueue::getQueue Jun 13 22:52:32 volumio go-librespot[3227]: time="2025-06-13T22:52:32-07:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 13 22:52:32 volumio go-librespot[3227]: time="2025-06-13T22:52:32-07:00" level=trace msg="emitting websocket event: volume" Jun 13 22:52:32 volumio volumio[2575]: SPOTIFY: received: {"type":"volume","data":{"value":20,"max":100}} Jun 13 22:52:32 volumio volumio[2575]: SPOTIFY: RECEIVED SPOTIFY VOLUME 20 Jun 13 22:52:32 volumio volumio[2575]: SPOTIFY: received: {"type":"volume","data":{"value":20,"max":100}} Jun 13 22:52:32 volumio volumio[2575]: SPOTIFY: RECEIVED SPOTIFY VOLUME 20 Jun 13 22:52:33 volumio volumio[2575]: info: Getting Spotify volume Jun 13 22:52:33 volumio volumio[2575]: info: Spotify volume: 20 Jun 13 22:52:33 volumio volumio[2575]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 Jun 13 22:52:33 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:33 volumio volumio[2575]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Jun 13 22:52:34 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 13 22:52:35 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jun 13 22:52:35 volumio volumio[2575]: info: In handleBrowseUri, curUri=spotify:artist:5KGgAxYWMoCJduQhLpIH4v Jun 13 22:52:36 volumio volumio[2575]: info: Preload queue cleared Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:1M5Pf0AeALfIpQD7ygKHCR Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:2Rl4sR3qwWleSWRdXtTChA Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:4tIMmNEe4shxTGHTf6kdJE Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:531r0RqWGUM483CwvWMRJn Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:3O0hcNYfnKDaCRQdQ7V5J2 Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:1dEDgOuXpd3tP9P3X9W9MR Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:3jtikJaYAWwthKHvD1b3dx Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:0Wbw8uElokEULcjxUE2rjR Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:7kdQYT81XP6vwyssQyjg5W Jun 13 22:52:36 volumio volumio[2575]: info: Preloading song: spotify:track:417NJZjAjPLX0p7xf4H8uJ Jun 13 22:52:36 volumio volumio[2575]: info: Preload queue cleared Jun 13 22:52:36 volumio volumio[2575]: info: Preload queue cleared Jun 13 22:52:36 volumio volumio[2575]: info: Executing endpoint getSimilarArtists Jun 13 22:52:36 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Jun 13 22:52:36 volumio volumio[2575]: info: Executing endpoint metavolumio Jun 13 22:52:36 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 13 22:52:36 volumio volumio[2575]: error: Failed request for metavolumio API Jun 13 22:52:37 volumio volumio[2575]: info: CoreCommandRouter::volumioVolatilePlay Jun 13 22:52:37 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] play Jun 13 22:52:37 volumio volumio[2575]: ------------------------------------ BT MESSAGE: sendPlay skipped: activePlayer not bound or invalid Jun 13 22:52:40 volumio volumio[2575]: info: CoreCommandRouter::volumioVolatilePlay Jun 13 22:52:40 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] play Jun 13 22:52:40 volumio volumio[2575]: ------------------------------------ BT MESSAGE: sendPlay skipped: activePlayer not bound or invalid Jun 13 22:52:42 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 13 22:52:42 volumio volumio[2575]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jun 13 22:52:42 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jun 13 22:52:42 volumio volumio[2575]: info: Received Get System Version Jun 13 22:52:42 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 13 22:52:42 volumio volumio[2575]: info: Received Get System Info Jun 13 22:52:42 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:52:42 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:52:42 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:52:42 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:42 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:52:43 volumio volumio[2575]: info: Preload queue cleared Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::ClearQueue Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::stop Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::serviceStop Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::serviceStop Jun 13 22:52:43 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] stop Jun 13 22:52:43 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput Jun 13 22:52:43 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [dbus-next] Disabling Bluetooth Audio Output Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::clearPlayQueue Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::saveQueue Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioPushQueue Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::addQueueItems Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::addQueueItems Jun 13 22:52:43 volumio volumio[2575]: info: Preload queue cleared Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:1M5Pf0AeALfIpQD7ygKHCR Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:1M5Pf0AeALfIpQD7ygKHCR in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:1M5Pf0AeALfIpQD7ygKHCR Jun 13 22:52:43 volumio volumio[2575]: ------------------------------------ BT MESSAGE: Bluetooth audio output stopped Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1M5Pf0AeALfIpQD7ygKHCR","service":"spop","name":"Khói Thuốc Đợi Chờ","artist":"Phương Phương Thảo","album":"Khói Thuốc Đợi Chờ","type":"song","duration":301,"albumart":"https://i.scdn.co/image/ab67616d0000b27317db6647cb9fc27512a4868b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioPushQueue Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::saveQueue Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::updateTrackBlock Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::getTrackBlock Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioPlay Jun 13 22:52:43 volumio volumio[2575]: verbose: UNSET VOLATILE: Service: bluetooth Jun 13 22:52:43 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] detachBluetooth Jun 13 22:52:43 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput Jun 13 22:52:43 volumio volumio[2575]: ------------------------------------ BT MESSAGE: [dbus-next] Disabling Bluetooth Audio Output Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::play index 0 Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::addQueueItems Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::addQueueItems Jun 13 22:52:43 volumio volumio[2575]: info: Preload queue cleared Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:2Rl4sR3qwWleSWRdXtTChA Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:2Rl4sR3qwWleSWRdXtTChA in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:2Rl4sR3qwWleSWRdXtTChA Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:4tIMmNEe4shxTGHTf6kdJE Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:4tIMmNEe4shxTGHTf6kdJE in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:4tIMmNEe4shxTGHTf6kdJE Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:531r0RqWGUM483CwvWMRJn Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:531r0RqWGUM483CwvWMRJn in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:531r0RqWGUM483CwvWMRJn Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:3O0hcNYfnKDaCRQdQ7V5J2 Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:3O0hcNYfnKDaCRQdQ7V5J2 in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:3O0hcNYfnKDaCRQdQ7V5J2 Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:1dEDgOuXpd3tP9P3X9W9MR Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:1dEDgOuXpd3tP9P3X9W9MR in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:1dEDgOuXpd3tP9P3X9W9MR Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:3jtikJaYAWwthKHvD1b3dx Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:3jtikJaYAWwthKHvD1b3dx in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:3jtikJaYAWwthKHvD1b3dx Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:0Wbw8uElokEULcjxUE2rjR Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:0Wbw8uElokEULcjxUE2rjR in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:0Wbw8uElokEULcjxUE2rjR Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:7kdQYT81XP6vwyssQyjg5W Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:7kdQYT81XP6vwyssQyjg5W in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:7kdQYT81XP6vwyssQyjg5W Jun 13 22:52:43 volumio volumio[2575]: info: Adding Item to queue: spotify:track:417NJZjAjPLX0p7xf4H8uJ Jun 13 22:52:43 volumio volumio[2575]: info: Exploding uri spotify:track:417NJZjAjPLX0p7xf4H8uJ in service spop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: EXPLODING URI:spotify:track:417NJZjAjPLX0p7xf4H8uJ Jun 13 22:52:43 volumio volumio[2575]: ------------------------------------ BT MESSAGE: Bluetooth audio output disabled. Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::stop Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::resetVolumioState Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::getcurrentVolume Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioRetrievevolume Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::play index undefined Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioStop Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::stop Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::startPlaybackTimer Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioGetVisibleSources Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jun 13 22:52:43 volumio volumio[2575]: info: [1749880363795] ControllerSpotify::clearAddPlayTrack Jun 13 22:52:43 volumio volumio[2575]: info: Sending Spotify command with payload to local API: /player/play Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::pushState Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioPushState Jun 13 22:52:43 volumio volumio[2575]: info: MRS: Pushing multiroomSync output update for this device Jun 13 22:52:43 volumio volumio[2575]: info: MRS: Pushing multiroomSync output Jun 13 22:52:43 volumio volumio[2575]: error: Help! Some callbacks for volumioPushState are crashing! Jun 13 22:52:43 volumio volumio[2575]: error: Cannot read properties of undefined (reading 'sendVolumeMute') Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::updateTrackBlock Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::getTrackBlock Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioRetrievevolume Jun 13 22:52:43 volumio volumio[2575]: info: PeppySpectrum ---peppyspectrum status stop Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: SPOTIFY VOLUME 20 Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: VOLUMIO VOLUME 20 Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: DELTA VOLUME ENOUGH: false Jun 13 22:52:43 volumio sudo[3276]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Jun 13 22:52:43 volumio sudo[3276]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:52:43 volumio volumio[2575]: info: CoreStateMachine::pushState Jun 13 22:52:43 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:52:43 volumio volumio[2575]: info: CoreCommandRouter::volumioPushState Jun 13 22:52:43 volumio volumio[2575]: info: MRS: Pushing multiroomSync output update for this device Jun 13 22:52:43 volumio volumio[2575]: info: MRS: Pushing multiroomSync output Jun 13 22:52:43 volumio volumio[2575]: error: Help! Some callbacks for volumioPushState are crashing! Jun 13 22:52:43 volumio volumio[2575]: error: Cannot read properties of undefined (reading 'sendVolumeMute') Jun 13 22:52:43 volumio volumio[2575]: info: PeppySpectrum ---peppyspectrum status stop Jun 13 22:52:43 volumio sudo[3279]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: SPOTIFY VOLUME 20 Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: VOLUMIO VOLUME 20 Jun 13 22:52:43 volumio volumio[2575]: SPOTIFY: DELTA VOLUME ENOUGH: false Jun 13 22:52:43 volumio sudo[3279]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:52:43 volumio sudo[3276]: pam_unix(sudo:session): session closed for user root Jun 13 22:52:43 volumio volumio[2575]: info: peppyspectrum Daemon Stop Jun 13 22:52:43 volumio go-librespot[3227]: time="2025-06-13T22:52:43-07:00" level=debug msg="resolved context of track" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:43 volumio go-librespot[3227]: time="2025-06-13T22:52:43-07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:43 volumio go-librespot[3227]: time="2025-06-13T22:52:43-07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:43 volumio sudo[3279]: pam_unix(sudo:session): session closed for user root Jun 13 22:52:43 volumio volumio[2575]: info: peppyspectrum Daemon Stop Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4tIMmNEe4shxTGHTf6kdJE","service":"spop","name":"Mưa Tuyết","artist":"Phương Phương Thảo","album":"Khói Thuốc Đợi Chờ","type":"song","duration":267,"albumart":"https://i.scdn.co/image/ab67616d0000b27317db6647cb9fc27512a4868b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2Rl4sR3qwWleSWRdXtTChA","service":"spop","name":"Vĩnh Biệt Màu Xanh","artist":"Phương Phương Thảo","album":"Khói Thuốc Đợi Chờ","type":"song","duration":274,"albumart":"https://i.scdn.co/image/ab67616d0000b27317db6647cb9fc27512a4868b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3jtikJaYAWwthKHvD1b3dx","service":"spop","name":"Đợi Anh Đến Hoa Cũng Tàn","artist":"Phương Phương Thảo","album":"Khói Thuốc Đợi Chờ","type":"song","duration":359,"albumart":"https://i.scdn.co/image/ab67616d0000b27317db6647cb9fc27512a4868b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=trace msg="emitting websocket event: will_play" Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1M5Pf0AeALfIpQD7ygKHCR","play_origin":"go-librespot"}} Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1M5Pf0AeALfIpQD7ygKHCR","play_origin":"go-librespot"}} Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3O0hcNYfnKDaCRQdQ7V5J2","service":"spop","name":"Con Tim Đang Cố Quên","artist":"Phương Phương Thảo","album":"Khói Thuốc Đợi Chờ","type":"song","duration":308,"albumart":"https://i.scdn.co/image/ab67616d0000b27317db6647cb9fc27512a4868b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0Wbw8uElokEULcjxUE2rjR","service":"spop","name":"Đừng Hỏi Vì Sao Tôi Nhớ Người","artist":"Phương Phương Thảo","album":"Khói Thuốc Đợi Chờ","type":"song","duration":285,"albumart":"https://i.scdn.co/image/ab67616d0000b27317db6647cb9fc27512a4868b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7kdQYT81XP6vwyssQyjg5W","service":"spop","name":"Hoa Bằng Lăng","artist":"Phương Phương Thảo","album":"Khói Thuốc Đợi Chờ","type":"song","duration":348,"albumart":"https://i.scdn.co/image/ab67616d0000b27317db6647cb9fc27512a4868b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1144" Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:531r0RqWGUM483CwvWMRJn","service":"spop","name":"Ga Chiều Phố Nhỏ","artist":"Phương Phương Thảo","album":"Cho Người Tình Lỡ","type":"song","duration":359,"albumart":"https://i.scdn.co/image/ab67616d0000b27331db835f98aaadf86f61d0bb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:417NJZjAjPLX0p7xf4H8uJ","service":"spop","name":"Cho Người Tình Lỡ","artist":"Phương Phương Thảo","album":"Cho Người Tình Lỡ","type":"song","duration":356,"albumart":"https://i.scdn.co/image/ab67616d0000b27331db835f98aaadf86f61d0bb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1dEDgOuXpd3tP9P3X9W9MR","service":"spop","name":"Thần Thoại","artist":"Phương Phương Thảo","album":"Thần Thoại","type":"song","duration":265,"albumart":"https://i.scdn.co/image/ab67616d0000b2738bbd758184c45c003088f75b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 13 22:52:44 volumio volumio[2575]: info: CoreCommandRouter::volumioPushQueue Jun 13 22:52:44 volumio volumio[2575]: info: CorePlayQueue::saveQueue Jun 13 22:52:44 volumio volumio[2575]: info: CoreStateMachine::updateTrackBlock Jun 13 22:52:44 volumio volumio[2575]: info: CorePlayQueue::getTrackBlock Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="selected format OGG_VORBIS_320 (7721ad3656e2e4f83d92b0fa61262fe92722b93b)" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="requested aes key for file 7721ad3656e2e4f83d92b0fa61262fe92722b93b, gid: 1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:44 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 13 22:52:44 volumio volumio[2575]: info: Received Get System Info Jun 13 22:52:44 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 13 22:52:44 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 13 22:52:44 volumio volumio[2575]: info: Discovery: Getting this device information Jun 13 22:52:44 volumio volumio[2575]: info: CoreCommandRouter::volumioGetState Jun 13 22:52:44 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:52:44 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="fetched first chunk of 21, total size is 10565868 bytes" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="created new output device" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=info msg="loaded track \"Khói Thuốc Đợi Chờ\" (paused: false, position: 0ms, duration: 301166ms, prefetched: false)" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=trace msg="scheduling prefetch in 271s" Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=trace msg="emitting websocket event: metadata" Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1M5Pf0AeALfIpQD7ygKHCR","name":"Khói Thuốc Đợi Chờ","artist_names":["Phương Phương Thảo"],"album_name":"Khói Thuốc Đợi Chờ","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0217db6647cb9fc27512a4868b","position":0,"duration":301166,"release_date":"year:2022 month:1 day:1","track_number":1,"disc_number":1}} Jun 13 22:52:44 volumio volumio[2575]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1M5Pf0AeALfIpQD7ygKHCR","name":"Khói Thuốc Đợi Chờ","artist_names":["Phương Phương Thảo"],"album_name":"Khói Thuốc Đợi Chờ","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0217db6647cb9fc27512a4868b","position":0,"duration":301166,"release_date":"year:2022 month:1 day:1","track_number":1,"disc_number":1}} Jun 13 22:52:44 volumio go-librespot[3227]: time="2025-06-13T22:52:44-07:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:44 volumio go-librespot[3227]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jun 13 22:52:44 volumio go-librespot[3226]: Aborted Jun 13 22:52:44 volumio volumio[2575]: info: Connection to go-librespot Websocket closed Jun 13 22:52:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jun 13 22:52:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 13 22:52:44 volumio volumio[2575]: info: Connection to go-librespot Websocket closed Jun 13 22:52:45 volumio volumio[2575]: info: Executing endpoint metavolumio Jun 13 22:52:45 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 13 22:52:45 volumio volumio[2575]: info: Executing endpoint metavolumio Jun 13 22:52:45 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 13 22:52:45 volumio volumio[2575]: info: Executing endpoint metavolumio Jun 13 22:52:45 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jun 13 22:52:46 volumio volumio[2575]: error: Failed request for metavolumio API Jun 13 22:52:47 volumio volumio[2575]: info: Initializing connection to go-librespot Websocket Jun 13 22:52:47 volumio volumio[2575]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 13 22:52:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jun 13 22:52:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 13 22:52:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 13 22:52:48 volumio go-librespot[3284]: go-librespot daemon starting... Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=info msg="running go-librespot 0.2.0" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=debug msg="app state loaded" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=info msg="zeroconf server listening on port 41035" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=debug msg="obtained new client token: AADg2qpoh/2rm5Vsgw70pX9ysWt1AVlwlRQBY4dzBbFLw2Cp82zqJDBlBsOXK0P9JW3IUffmvSLWc5bMWpfYMDS2gQAFrMZ+eeghjlKw1x8UgCTA62/A9c20Hx4zNcoy4J1LP4sHDvhELb9Uz+FimuNWfK6PWvybhWQMXRgj20xdALBwosxZCEewPtBOYIJmpCQ+H8QBaL093O2PFWs0yRYwwvOMdsUAwDMDJM7loIenFbdATqrMZNAG" Jun 13 22:52:48 volumio volumio[2575]: info: VolumeController::SetAlsaVolume100 Jun 13 22:52:48 volumio volumio[2575]: info: CoreStateMachine::pushState Jun 13 22:52:48 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:52:48 volumio volumio[2575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 13 22:52:48 volumio volumio[2575]: info: CoreCommandRouter::volumioPushState Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 13 22:52:48 volumio volumio[2575]: info: MRS: Pushing multiroomSync output update for this device Jun 13 22:52:48 volumio volumio[2575]: info: MRS: Pushing multiroomSync output Jun 13 22:52:48 volumio volumio[2575]: error: Help! Some callbacks for volumioPushState are crashing! Jun 13 22:52:48 volumio volumio[2575]: error: Cannot read properties of undefined (reading 'sendVolumeMute') Jun 13 22:52:48 volumio volumio[2575]: info: PeppySpectrum ---peppyspectrum status stop Jun 13 22:52:48 volumio sudo[3294]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Jun 13 22:52:48 volumio sudo[3294]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 13 22:52:48 volumio volumio[2575]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 13 22:52:48 volumio volumio[2575]: SPOTIFY: SPOTIFY VOLUME 20 Jun 13 22:52:48 volumio volumio[2575]: SPOTIFY: VOLUMIO VOLUME 100 Jun 13 22:52:48 volumio volumio[2575]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 13 22:52:48 volumio volumio[2575]: info: Setting Spotify Volume from Volumio: 100 Jun 13 22:52:48 volumio sudo[3294]: pam_unix(sudo:session): session closed for user root Jun 13 22:52:48 volumio volumio[2575]: info: peppyspectrum Daemon Stop Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=debug msg="completed keyexchange" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=debug msg="completed challenge" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=info msg="authenticated AP as 22wbf3d2bwtkml5jrta5crf2a" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=info msg="authenticated Login5 as 22wbf3d2bwtkml5jrta5crf2a" Jun 13 22:52:48 volumio go-librespot[3285]: time="2025-06-13T22:52:48-07:00" level=debug msg="initializing zeroconf session, username: 22wbf3d2bwtkml5jrta5crf2a" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=debug msg="dealer connection opened" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=trace msg="starting accesspoint recv loop" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=trace msg="starting dealer recv loop" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=trace msg="received accesspoint ping" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=debug msg="received connection id: M2IzYjIyNGEtM2Q2ZC00YmYyLWIwZjAtZjQxNTYwNzdhY2ZiK2RlYWxlcit0Y3A6Ly8wYWNiZDg2Ni5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArMUVBMzBFMTgxMzBBNUQyQkZFNEZENzBFQ0Q3RTdDQTlBNUNGMjg1NEJFMzhFNEY0QTI1OTU4RkI3QTJFQzcxMw==" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=trace msg="received accesspoint pong ack" Jun 13 22:52:49 volumio go-librespot[3285]: time="2025-06-13T22:52:49-07:00" level=debug msg="put connect state because NEW_DEVICE" Jun 13 22:52:50 volumio volumio[2575]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Jun 13 22:52:50 volumio volumio[2575]: info: Sending Spotify command with payload to local API: /player/volume Jun 13 22:52:50 volumio go-librespot[3285]: time="2025-06-13T22:52:50-07:00" level=debug msg="update volume to 65535/65535" Jun 13 22:52:50 volumio volumio[2575]: info: Initializing connection to go-librespot Websocket Jun 13 22:52:50 volumio go-librespot[3285]: time="2025-06-13T22:52:50-07:00" level=debug msg="new websocket client" Jun 13 22:52:50 volumio volumio[2575]: info: Connection to go-librespot Websocket established Jun 13 22:52:50 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Jun 13 22:52:51 volumio go-librespot[3285]: time="2025-06-13T22:52:51-07:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 13 22:52:51 volumio go-librespot[3285]: time="2025-06-13T22:52:51-07:00" level=trace msg="emitting websocket event: volume" Jun 13 22:52:51 volumio volumio[2575]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Jun 13 22:52:51 volumio volumio[2575]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Jun 13 22:52:52 volumio volumio[2575]: info: CoreCommandRouter::volumioPlay Jun 13 22:52:52 volumio volumio[2575]: info: CoreStateMachine::play index undefined Jun 13 22:52:52 volumio volumio[2575]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 13 22:52:52 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:52:52 volumio volumio[2575]: info: CoreStateMachine::startPlaybackTimer Jun 13 22:52:52 volumio volumio[2575]: info: CorePlayQueue::getTrack 0 Jun 13 22:52:52 volumio volumio[2575]: info: [1749880372884] ControllerSpotify::clearAddPlayTrack Jun 13 22:52:52 volumio volumio[2575]: info: Sending Spotify command with payload to local API: /player/play Jun 13 22:52:52 volumio go-librespot[3285]: time="2025-06-13T22:52:52-07:00" level=debug msg="resolved context of track" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:52 volumio go-librespot[3285]: time="2025-06-13T22:52:52-07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:52 volumio go-librespot[3285]: time="2025-06-13T22:52:52-07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=trace msg="emitting websocket event: will_play" Jun 13 22:52:53 volumio volumio[2575]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1M5Pf0AeALfIpQD7ygKHCR","play_origin":"go-librespot"}} Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=debug msg="selected format OGG_VORBIS_320 (7721ad3656e2e4f83d92b0fa61262fe92722b93b)" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=debug msg="requested aes key for file 7721ad3656e2e4f83d92b0fa61262fe92722b93b, gid: 1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=debug msg="fetched first chunk of 21, total size is 10565868 bytes" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=debug msg="created new output device" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=info msg="loaded track \"Khói Thuốc Đợi Chờ\" (paused: false, position: 0ms, duration: 301166ms, prefetched: false)" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=trace msg="scheduling prefetch in 271s" Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=trace msg="emitting websocket event: metadata" Jun 13 22:52:53 volumio volumio[2575]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1M5Pf0AeALfIpQD7ygKHCR","name":"Khói Thuốc Đợi Chờ","artist_names":["Phương Phương Thảo"],"album_name":"Khói Thuốc Đợi Chờ","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0217db6647cb9fc27512a4868b","position":0,"duration":301166,"release_date":"year:2022 month:1 day:1","track_number":1,"disc_number":1}} Jun 13 22:52:53 volumio go-librespot[3285]: time="2025-06-13T22:52:53-07:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:1M5Pf0AeALfIpQD7ygKHCR" Jun 13 22:52:53 volumio go-librespot[3285]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jun 13 22:52:53 volumio go-librespot[3284]: Aborted Jun 13 22:52:53 volumio volumio[2575]: info: Connection to go-librespot Websocket closed Jun 13 22:52:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jun 13 22:52:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 13 22:52:53 volumio volumio[2575]: info: Getting Spotify volume Jun 13 22:52:53 volumio volumio[2575]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 13 22:52:53 volumio volumio[2575]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 13 22:52:53 volumio volumio[2575]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jun 13 22:52:53 volumio volumio[2575]: errno: -111, Jun 13 22:52:53 volumio volumio[2575]: code: 'ECONNREFUSED', Jun 13 22:52:53 volumio volumio[2575]: syscall: 'connect', Jun 13 22:52:53 volumio volumio[2575]: address: '127.0.0.1', Jun 13 22:52:53 volumio volumio[2575]: port: 9879, Jun 13 22:52:53 volumio volumio[2575]: response: undefined Jun 13 22:52:53 volumio volumio[2575]: } Jun 13 22:52:53 volumio volumio[2575]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 13 22:52:54 volumio sudo[3328]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-06-13 22:51' Jun 13 22:52:54 volumio sudo[3328]: 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="4a70cb031e64a8e498efc3e29470650871ff7d54" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat May 31 04:09:10 UTC 2025" VOLUMIO_VERSION="4.005" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="f9bd4447a30d4b2c74b3880e7a50e48b"