-- Logs begin at Wed 2024-10-30 04:12:16 CET, end at Sat 2025-05-24 17:27:22 CEST. -- May 24 17:26:37 minidsp-shd ntpd[779]: receive: Unexpected origin timestamp 0xeacc22ad.7283dd03 does not match aorg 0000000000.00000000 from server@185.35.202.197 xmt 0xebdc63ad.80346224 May 24 17:26:37 minidsp-shd ntpd[779]: receive: Unexpected origin timestamp 0xeacc22ad.728dc3ea does not match aorg 0000000000.00000000 from server@80.203.110.169 xmt 0xebdc63ad.80a8826a May 24 17:26:37 minidsp-shd systemd[1]: Starting Daily apt download activities... May 24 17:26:38 minidsp-shd volumio[793]: info: Loading plugin "network"... May 24 17:26:38 minidsp-shd volumio[793]: info: Refreshing Cached IP Addresses May 24 17:26:38 minidsp-shd sudo[882]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 24 17:26:38 minidsp-shd sudo[882]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:26:38 minidsp-shd volumio[793]: info: Loading plugin "services"... May 24 17:26:38 minidsp-shd sudo[885]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 24 17:26:38 minidsp-shd sudo[882]: pam_unix(sudo:session): session closed for user root May 24 17:26:38 minidsp-shd sudo[885]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:26:39 minidsp-shd volumio[793]: info: Loading plugin "alsa_controller"... May 24 17:26:39 minidsp-shd sudo[885]: pam_unix(sudo:session): session closed for user root May 24 17:26:39 minidsp-shd systemd[1]: apt-daily.service: Succeeded. May 24 17:26:39 minidsp-shd systemd[1]: Started Daily apt download activities. May 24 17:26:39 minidsp-shd sudo[888]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 24 17:26:39 minidsp-shd sudo[888]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:26:39 minidsp-shd systemd[1]: Starting Daily apt upgrade and clean activities... May 24 17:26:39 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 24 17:26:39 minidsp-shd volumio[793]: info: Loading plugin "wizard"... May 24 17:26:39 minidsp-shd volumio[793]: info: Loading plugin "networkfs"... May 24 17:26:39 minidsp-shd volumio[793]: info: Starting Udev Watcher for removable devices May 24 17:26:39 minidsp-shd sudo[909]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.10.197/USB /mnt/NAS/USB May 24 17:26:39 minidsp-shd sudo[909]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:26:39 minidsp-shd kernel: FS-Cache: Loaded May 24 17:26:39 minidsp-shd volumio[793]: info: Ignoring mount for partition: BOOT May 24 17:26:39 minidsp-shd volumio[793]: info: Ignoring mount for partition: volumio May 24 17:26:39 minidsp-shd volumio[793]: info: Ignoring mount for partition: volumio_data May 24 17:26:39 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 24 17:26:39 minidsp-shd volumio[793]: info: Loading plugin "volumio_command_line_client"... May 24 17:26:39 minidsp-shd volumio[793]: info: Loading plugin "upnp"... May 24 17:26:39 minidsp-shd volumio[793]: info: [1748100399508] Starting Upmpd Daemon May 24 17:26:39 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 24 17:26:39 minidsp-shd volumio[793]: info: Loading plugin "my_music"... May 24 17:26:39 minidsp-shd volumio[793]: info: Loading plugin "mpd"... May 24 17:26:39 minidsp-shd kernel: FS-Cache: Netfs 'cifs' registered for caching May 24 17:26:39 minidsp-shd kernel: Key type cifs.spnego registered May 24 17:26:39 minidsp-shd kernel: Key type cifs.idmap registered May 24 17:26:39 minidsp-shd kernel: CIFS: Attempting to mount //192.168.10.197/USB May 24 17:26:39 minidsp-shd kernel: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3 (or SMB2.1) specify vers=1.0 on mount. May 24 17:26:39 minidsp-shd sudo[909]: pam_unix(sudo:session): session closed for user root May 24 17:26:40 minidsp-shd systemd[1]: apt-daily-upgrade.service: Succeeded. May 24 17:26:40 minidsp-shd systemd[1]: Started Daily apt upgrade and clean activities. May 24 17:26:40 minidsp-shd systemd[1]: systemd-fsckd.service: Succeeded. May 24 17:26:40 minidsp-shd volumio[793]: info: Loading plugin "upnp_browser"... May 24 17:26:40 minidsp-shd sh[389]: timed out May 24 17:26:40 minidsp-shd sh[389]: dhcpcd exited May 24 17:26:40 minidsp-shd dhcpcd[429]: timed out May 24 17:26:40 minidsp-shd sh[389]: ifup: failed to bring up eth0 May 24 17:26:40 minidsp-shd dhcpcd[429]: dhcpcd exited May 24 17:26:40 minidsp-shd systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 24 17:26:40 minidsp-shd systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 24 17:26:41 minidsp-shd volumio[793]: info: Loading plugin "bluetooth"... May 24 17:26:41 minidsp-shd volumio[793]: info: [1748100401640] Starting BluetoothController May 24 17:26:41 minidsp-shd volumio[793]: info: Loading plugin "alarm-clock"... May 24 17:26:42 minidsp-shd volumio[793]: info: Loading plugin "manifestui"... May 24 17:26:42 minidsp-shd volumio[793]: info: Loading plugin "metavolumio"... May 24 17:26:43 minidsp-shd sudo[888]: pam_unix(sudo:session): session closed for user root May 24 17:26:45 minidsp-shd volumio[793]: info: Loading plugin "airplay_emulation"... May 24 17:26:45 minidsp-shd volumio[793]: info: Starting Shairport Sync May 24 17:26:45 minidsp-shd volumio[793]: info: Loading plugin "cd_controller"... May 24 17:26:45 minidsp-shd volumio[793]: info: Loading plugin "last_100"... May 24 17:26:45 minidsp-shd volumio[793]: info: Loading plugin "raat"... May 24 17:26:46 minidsp-shd volumio[793]: info: RAAT Plugin loaded May 24 17:26:46 minidsp-shd volumio[793]: info: Adding restartRAATSocket REST API Endpoint May 24 17:26:46 minidsp-shd volumio[793]: info: Adding restartRAATSocket REST Endpoint for plugin: music_service/raat May 24 17:26:46 minidsp-shd volumio[793]: info: Loading plugin "streaming_services"... May 24 17:26:48 minidsp-shd volumio[793]: info: Starting Streaming Service Transparent Proxy May 24 17:26:48 minidsp-shd volumio[793]: info: Loading plugin "tidalconnect"... May 24 17:26:48 minidsp-shd volumio[793]: info: Loading plugin "webradio"... May 24 17:26:49 minidsp-shd volumio[793]: info: Loading plugin "i2s_dacs"... May 24 17:26:49 minidsp-shd volumio[793]: info: I2S DAC not set, start Auto-detection May 24 17:26:49 minidsp-shd volumio[793]: info: Loading plugin "volumiodiscovery"... May 24 17:26:49 minidsp-shd volumio[793]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 24 17:26:49 minidsp-shd volumio[793]: *** WARNING *** Please fix your application to use the native API of Avahi! May 24 17:26:49 minidsp-shd node[793]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 24 17:26:49 minidsp-shd volumio[793]: *** WARNING *** For more information see May 24 17:26:49 minidsp-shd volumio[793]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 24 17:26:49 minidsp-shd volumio[793]: *** WARNING *** Please fix your application to use the native API of Avahi! May 24 17:26:49 minidsp-shd volumio[793]: *** WARNING *** For more information see May 24 17:26:49 minidsp-shd node[793]: *** WARNING *** Please fix your application to use the native API of Avahi! May 24 17:26:49 minidsp-shd node[793]: *** WARNING *** For more information see May 24 17:26:49 minidsp-shd node[793]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 24 17:26:49 minidsp-shd node[793]: *** WARNING *** Please fix your application to use the native API of Avahi! May 24 17:26:49 minidsp-shd node[793]: *** WARNING *** For more information see May 24 17:26:49 minidsp-shd volumio[793]: info: Applying required configuration parameters for plugin volumiodiscovery May 24 17:26:49 minidsp-shd volumio[793]: info: Discovery: Started advertising with name: miniDSP SHD May 24 17:26:49 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 24 17:26:49 minidsp-shd volumio[793]: info: Loading plugin "spop"... May 24 17:26:49 minidsp-shd volumio-remote-updater[460]: [2025-05-24 17:26:49] [connect] Successful connection May 24 17:26:50 minidsp-shd volumio[793]: STREAMING PROXY: Starting server on port 3245 May 24 17:26:50 minidsp-shd volumio[793]: Node JS runtime: 14 May 24 17:26:52 minidsp-shd volumio[793]: info: Loading plugin "multiroom"... May 24 17:26:55 minidsp-shd volumio[793]: info: Applying required configuration parameters for plugin multiroom May 24 17:26:55 minidsp-shd sudo[985]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom May 24 17:26:55 minidsp-shd sudo[985]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:26:55 minidsp-shd sudo[985]: pam_unix(sudo:session): session closed for user root May 24 17:26:55 minidsp-shd volumio[793]: info: MRS: MultiRoom plugin initialized May 24 17:26:55 minidsp-shd volumio[793]: info: MRS: STOPPING SNAPCLIENT May 24 17:26:55 minidsp-shd volumio[793]: info: MRS: Snap server stop May 24 17:26:55 minidsp-shd volumio[793]: info: MRS: STOPPING volumioStreaming May 24 17:26:55 minidsp-shd sudo[1001]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient May 24 17:26:55 minidsp-shd sudo[1001]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:26:55 minidsp-shd sudo[1003]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver May 24 17:26:55 minidsp-shd sudo[1003]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:26:55 minidsp-shd sudo[1001]: pam_unix(sudo:session): session closed for user root May 24 17:26:55 minidsp-shd volumio[793]: info: Loading plugin "outputs"... May 24 17:26:55 minidsp-shd sudo[1006]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming May 24 17:26:55 minidsp-shd sudo[1006]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:26:55 minidsp-shd volumio[793]: info: Loading plugin "albumart"... May 24 17:26:55 minidsp-shd sudo[1009]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* May 24 17:26:55 minidsp-shd sudo[1009]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:26:55 minidsp-shd sudo[1003]: pam_unix(sudo:session): session closed for user root May 24 17:26:55 minidsp-shd sudo[1009]: pam_unix(sudo:session): session closed for user root May 24 17:26:55 minidsp-shd volumio[793]: info: Loading plugin "ms_surface_dial"... May 24 17:26:55 minidsp-shd sudo[1006]: pam_unix(sudo:session): session closed for user root May 24 17:26:56 minidsp-shd volumio[793]: Forking 3 albumart workers May 24 17:26:57 minidsp-shd volumio[793]: info: Applying required configuration parameters for plugin ms_surface_dial May 24 17:26:57 minidsp-shd volumio[793]: info: Plugin example_plugin is not enabled May 24 17:26:57 minidsp-shd volumio[793]: info: Loading plugin "hi_res_audio"... May 24 17:26:58 minidsp-shd volumio[793]: Starting albumart workers May 24 17:26:58 minidsp-shd volumio[793]: Starting albumart workers May 24 17:26:58 minidsp-shd volumio[793]: Starting albumart workers May 24 17:27:00 minidsp-shd volumio[793]: info: Applying required configuration parameters for plugin hi_res_audio May 24 17:27:00 minidsp-shd volumio[793]: info: Loading plugin "inputs"... May 24 17:27:01 minidsp-shd volumio[793]: info: Loading plugin "qobuz"... May 24 17:27:04 minidsp-shd volumio[793]: info: Loading plugin "tidal"... May 24 17:27:04 minidsp-shd volumio-remote-updater[460]: [2025-05-24 17:27:04] [connect] Successful connection May 24 17:27:06 minidsp-shd volumio[793]: info: Loading plugin "oem_helper"... May 24 17:27:08 minidsp-shd volumio[793]: info: Applying required configuration parameters for plugin oem_helper May 24 17:27:08 minidsp-shd volumio[793]: info: Loading plugin "updater_comm"... May 24 17:27:08 minidsp-shd volumio[793]: info: Plugin mpdemulation is not enabled May 24 17:27:08 minidsp-shd volumio[793]: info: Loading plugin "rest_api"... May 24 17:27:08 minidsp-shd volumio[793]: info: Loading plugin "websocket"... May 24 17:27:08 minidsp-shd volumio[793]: info: Loading i18n strings for locale en May 24 17:27:08 minidsp-shd volumio[793]: Updating browse sources language May 24 17:27:08 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::initPlayerControls May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 17:27:09 minidsp-shd volumio[793]: Express server listening on port 3000 May 24 17:27:09 minidsp-shd volumio[793]: [Metrics] WebUI: 37s 59.78ms May 24 17:27:09 minidsp-shd volumio[793]: info: CoreStateMachine::resetVolumioState May 24 17:27:09 minidsp-shd volumio[793]: info: CoreStateMachine::getcurrentVolume May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioRetrievevolume May 24 17:27:09 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:09 minidsp-shd volumio[793]: info: CorePlayQueue::getTrack 0 May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 17:27:09 minidsp-shd sudo[1075]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 24 17:27:09 minidsp-shd sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: inputs , getVolume May 24 17:27:09 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: inputs , getDSP May 24 17:27:09 minidsp-shd sudo[1075]: pam_unix(sudo:session): session closed for user root May 24 17:27:09 minidsp-shd sudo[1077]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 24 17:27:09 minidsp-shd sudo[1077]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:09 minidsp-shd sudo[1077]: pam_unix(sudo:session): session closed for user root May 24 17:27:09 minidsp-shd volumio[793]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' May 24 17:27:09 minidsp-shd volumio[793]: info: Completed loading Core Plugins May 24 17:27:09 minidsp-shd volumio[793]: info: Preparing to generate the ALSA configuration file May 24 17:27:09 minidsp-shd volumio[793]: info: Cannot read play queue from file May 24 17:27:09 minidsp-shd volumio[793]: info: MRS: Removed streaming files May 24 17:27:09 minidsp-shd volumio[793]: info: MRS: volumioStreaming STOPPED May 24 17:27:09 minidsp-shd volumio[793]: info: MRS: SNAPSERVER STOPPED May 24 17:27:09 minidsp-shd volumio[793]: info: MRS: SNAPCLIENT STOPPED May 24 17:27:09 minidsp-shd volumio[793]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision May 24 17:27:09 minidsp-shd volumio[793]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf May 24 17:27:09 minidsp-shd volumio[793]: info: Reading ALSA contributions from plugins. May 24 17:27:10 minidsp-shd volumio[793]: info: CoreStateMachine::setRepeat false single undefined May 24 17:27:10 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:10 minidsp-shd volumio[793]: info: CorePlayQueue::getTrack 0 May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:10 minidsp-shd volumio[793]: info: CoreStateMachine::setRandom null May 24 17:27:10 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:10 minidsp-shd volumio[793]: info: CorePlayQueue::getTrack 0 May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:10 minidsp-shd volumio[793]: info: Setting Device type: NanoPi NEO 3 May 24 17:27:10 minidsp-shd volumio[793]: info: Asound.conf file unchanged, so no further update is needed May 24 17:27:10 minidsp-shd volumio[793]: info: Output device has changed, restarting MPD May 24 17:27:10 minidsp-shd sudo[1086]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 24 17:27:10 minidsp-shd sudo[1086]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:10 minidsp-shd systemd[1]: Started UPnP Renderer front-end to MPD. May 24 17:27:10 minidsp-shd sudo[1089]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 24 17:27:10 minidsp-shd volumio[793]: info: Output device has changed, restarting Shairport Sync May 24 17:27:10 minidsp-shd sudo[1089]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 17:27:10 minidsp-shd sudo[1089]: pam_unix(sudo:session): session closed for user root May 24 17:27:10 minidsp-shd sudo[1086]: pam_unix(sudo:session): session closed for user root May 24 17:27:10 minidsp-shd sudo[1093]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 24 17:27:10 minidsp-shd sudo[1093]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:10 minidsp-shd systemd[1]: Listening on mpd.socket. May 24 17:27:10 minidsp-shd systemd[1]: Starting Music Player Daemon... May 24 17:27:10 minidsp-shd volumio[793]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 24 17:27:10 minidsp-shd volumio[793]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:10 minidsp-shd volumio[793]: info: ___________ START PLUGINS ___________ May 24 17:27:10 minidsp-shd volumio[793]: info: ControllerMpd::onStart: Initializing MPD May 24 17:27:10 minidsp-shd volumio[793]: info: Creating MPD Configuration file May 24 17:27:10 minidsp-shd sudo[1102]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 17:27:10 minidsp-shd sudo[1102]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 24 17:27:10 minidsp-shd volumio[793]: info: [1748100430804] CoreMusicLibrary::Adding element Media Servers May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 17:27:10 minidsp-shd sudo[1102]: pam_unix(sudo:session): session closed for user root May 24 17:27:10 minidsp-shd sudo[1104]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 24 17:27:10 minidsp-shd sudo[1104]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 24 17:27:10 minidsp-shd systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM May 24 17:27:10 minidsp-shd systemd[1]: mpd.service: Succeeded. May 24 17:27:10 minidsp-shd systemd[1]: Stopped Music Player Daemon. May 24 17:27:10 minidsp-shd volumio[793]: info: Adding Manifest REST API Endpoints May 24 17:27:10 minidsp-shd volumio[793]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui May 24 17:27:10 minidsp-shd systemd[1]: Starting Music Player Daemon... May 24 17:27:10 minidsp-shd volumio[793]: info: Adding METAVOLUMIO REST API Endpoints May 24 17:27:10 minidsp-shd volumio[793]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio May 24 17:27:10 minidsp-shd volumio[793]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio May 24 17:27:10 minidsp-shd volumio[793]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio May 24 17:27:10 minidsp-shd volumio[793]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:10 minidsp-shd sudo[1108]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name miniDSP SHD May 24 17:27:10 minidsp-shd sudo[1108]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:10 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 17:27:10 minidsp-shd sudo[1108]: pam_unix(sudo:session): session closed for user root May 24 17:27:11 minidsp-shd volumio[793]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 17:27:11 minidsp-shd volumio[793]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 24 17:27:11 minidsp-shd volumio[793]: info: Preparing CD Folders May 24 17:27:11 minidsp-shd volumio[793]: info: Adding CD REST API Endpoints May 24 17:27:11 minidsp-shd volumio[793]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller May 24 17:27:11 minidsp-shd volumio[793]: info: Starting UDEV Watcher for CD May 24 17:27:11 minidsp-shd volumio[793]: info: Detecting CD presence with UDEV May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 24 17:27:11 minidsp-shd volumio[793]: info: [1748100431210] CoreMusicLibrary::Adding element Last_100 May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 17:27:11 minidsp-shd volumio[793]: info: Starting RAAT Plugin May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections May 24 17:27:11 minidsp-shd volumio[793]: info: Additional UI Settings Added for plugin music_service/raat May 24 17:27:11 minidsp-shd volumio[793]: info: Streaming services startup May 24 17:27:11 minidsp-shd volumio[793]: info: Starting Streaming Daemon May 24 17:27:11 minidsp-shd sudo[1120]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 24 17:27:11 minidsp-shd sudo[1120]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:11 minidsp-shd sudo[1120]: pam_unix(sudo:session): session closed for user root May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 24 17:27:11 minidsp-shd volumio[793]: info: [1748100431458] CoreMusicLibrary::Adding element Webradio May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 24 17:27:11 minidsp-shd sudo[1127]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 24 17:27:11 minidsp-shd sudo[1127]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:11 minidsp-shd volumio[793]: info: Creating Spotify config file May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:11 minidsp-shd sudo[1127]: pam_unix(sudo:session): session closed for user root May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus May 24 17:27:11 minidsp-shd volumio[793]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration May 24 17:27:11 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:11 minidsp-shd dbus-daemon[466]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.8' (uid=1000 pid=793 comm="/usr/bin/node /volumio/index.js ") May 24 17:27:11 minidsp-shd volumio[793]: error: Hi Res Audio Failed Login: Missing Login Data May 24 17:27:11 minidsp-shd volumio[793]: info: Adding HIGHRESAUDIO REST API Endpoints May 24 17:27:11 minidsp-shd volumio[793]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio May 24 17:27:11 minidsp-shd systemd[1]: Starting Bluetooth service... May 24 17:27:12 minidsp-shd bluetoothd[1155]: Bluetooth daemon 5.23 May 24 17:27:12 minidsp-shd dbus-daemon[466]: [system] Successfully activated service 'org.bluez' May 24 17:27:12 minidsp-shd systemd[1]: Started Bluetooth service. May 24 17:27:12 minidsp-shd bluetoothd[1155]: Starting SDP server May 24 17:27:12 minidsp-shd bluetoothd[1155]: kernel lacks bnep-protocol support May 24 17:27:12 minidsp-shd bluetoothd[1155]: System does not support network plugin May 24 17:27:12 minidsp-shd bluetoothd[1155]: Bluetooth management interface 1.14 initialized May 24 17:27:12 minidsp-shd dbus-daemon[466]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.11' (uid=0 pid=1155 comm="/usr/local/libexec/bluetooth/bluetoothd ") May 24 17:27:12 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 24 17:27:12 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 17:27:12 minidsp-shd volumio[793]: info: Volumio Calling Home May 24 17:27:12 minidsp-shd systemd[1]: Starting Hostname Service... May 24 17:27:12 minidsp-shd volumio[793]: info: Stopping AccessToken refresher cron for QOBUZ May 24 17:27:12 minidsp-shd dbus-daemon[466]: [system] Successfully activated service 'org.freedesktop.hostname1' May 24 17:27:12 minidsp-shd systemd[1]: Started Hostname Service. May 24 17:27:12 minidsp-shd volumio[793]: info: AccessToken refresher cron started for QOBUZ May 24 17:27:12 minidsp-shd volumio[793]: info: Stopping AccessToken refresher cron May 24 17:27:12 minidsp-shd volumio[793]: info: AccessToken refresher cron started May 24 17:27:12 minidsp-shd volumio[793]: info: Adding TIDAL REST API Endpoints May 24 17:27:12 minidsp-shd volumio[793]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal May 24 17:27:12 minidsp-shd volumio[793]: info: Adding QOBUZ REST API Endpoints May 24 17:27:12 minidsp-shd volumio[793]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz May 24 17:27:12 minidsp-shd volumio[793]: info: Discovery: adding 7de2fe78-6056-4e2f-9f1b-de3300fc121e May 24 17:27:12 minidsp-shd volumio[793]: info: Discovery: Found device miniDSP SHD May 24 17:27:12 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioGetState May 24 17:27:12 minidsp-shd volumio[793]: info: CorePlayQueue::getTrack 0 May 24 17:27:12 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output for this device May 24 17:27:12 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:12 minidsp-shd volumio[793]: info: Adding audio output: May 24 17:27:12 minidsp-shd volumio[793]: info: Adding audio output: May 24 17:27:12 minidsp-shd volumio[793]: info: Serial port opened successfully May 24 17:27:13 minidsp-shd volumio[793]: error: Cannot start Volumio Streaming Daemon May 24 17:27:13 minidsp-shd volumio[793]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 24 17:27:13 minidsp-shd volumio[793]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 24 17:27:13 minidsp-shd volumio[793]: info: RAAT Albumart path created successfully May 24 17:27:13 minidsp-shd volumio[793]: error: Cannot set new Bluetooth Name : Error: Command failed: /usr/bin/sudo /bin/hciconfig hci0 name 'miniDSP SHD' May 24 17:27:13 minidsp-shd volumio[793]: Can't get device info: No such device May 24 17:27:13 minidsp-shd volumio[793]: info: MPD Permissions set May 24 17:27:13 minidsp-shd volumio[793]: info: MPD Permissions set May 24 17:27:13 minidsp-shd volumio[793]: info: Upmpdcli Daemon Started May 24 17:27:13 minidsp-shd volumio[793]: info: msSurfaceDial volumioupdatevolume callback: {"vol":78,"dbVolume":-28,"disableVolumeControl":false} May 24 17:27:13 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:13 minidsp-shd volumio[793]: info: CorePlayQueue::getTrack 0 May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:13 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output update for this device May 24 17:27:13 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume May 24 17:27:13 minidsp-shd volumio[793]: info: Ignoring ROON Volume update because of undefined data May 24 17:27:13 minidsp-shd volumio[793]: info: msSurfaceDial Managed Objs {"/org/bluez":{"org.freedesktop.DBus.Introspectable":{},"org.bluez.AgentManager1":{},"org.bluez.ProfileManager1":{}}} May 24 17:27:13 minidsp-shd volumio[793]: info: [msSurfaceDial init()] check /org/bluez May 24 17:27:13 minidsp-shd volumio[793]: info: [msSurfaceDial init()] Adapter: null; SurfaceDial: null May 24 17:27:13 minidsp-shd volumio[793]: info: msSurfaceDial BluetoothSurfaceDial init() - ready! May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::Reload Ui May 24 17:27:13 minidsp-shd volumio[793]: info: Volumio called home May 24 17:27:13 minidsp-shd volumio[793]: info: Spotify config file written May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP May 24 17:27:13 minidsp-shd volumio[793]: info: updateDSP function in raat called! May 24 17:27:13 minidsp-shd volumio[793]: info: Updating RAAT Signal Path May 24 17:27:13 minidsp-shd volumio[793]: error: Cannot write to RAAT Client: TypeError: Cannot read property 'write' of undefined May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: raat , reconfigureAndRestartRaat May 24 17:27:13 minidsp-shd volumio[793]: info: Reconfiguring and Restarting RAAT Plugin May 24 17:27:13 minidsp-shd sudo[1185]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 24 17:27:13 minidsp-shd sudo[1185]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd systemd[1]: Started go-librespot Daemon. May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: Not Reporting Auto name since its the default one May 24 17:27:13 minidsp-shd volumio[793]: info: RAAT Overriding default device vendor model May 24 17:27:13 minidsp-shd go-librespot[1191]: Librespot-go daemon starting... May 24 17:27:13 minidsp-shd volumio[793]: info: Adding MINIDSP Inputs May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 24 17:27:13 minidsp-shd volumio[793]: info: [1748100433334] CoreMusicLibrary::Adding element Inputs May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 24 17:27:13 minidsp-shd volumio[793]: info: [1748100433343] CoreMusicLibrary::Adding element Presets May 24 17:27:13 minidsp-shd sudo[1185]: pam_unix(sudo:session): session closed for user root May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 17:27:13 minidsp-shd volumio[793]: Cannot find translation for source Presets May 24 17:27:13 minidsp-shd volumio[793]: (node:793) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. May 24 17:27:13 minidsp-shd volumio[793]: (Use `node --trace-deprecation ...` to show where the warning was created) May 24 17:27:13 minidsp-shd volumio[793]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 1 May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:13+02:00" level=info msg="generated new device id: 1f2f779343bc6c5c6a532b773557254252ac2c4b" May 24 17:27:13 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:13+02:00" level=debug msg="stored credentials found for 1164747946" May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber May 24 17:27:13 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:13 minidsp-shd volumio[793]: info: No need to fix Spotify hosts May 24 17:27:14 minidsp-shd sudo[1213]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service May 24 17:27:14 minidsp-shd sudo[1213]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:14 minidsp-shd systemd[1]: Started Volumio Bluetooth Module. May 24 17:27:14 minidsp-shd sudo[1213]: pam_unix(sudo:session): session closed for user root May 24 17:27:14 minidsp-shd volumio[793]: info: CorePlayQueue::getTrack 0 May 24 17:27:14 minidsp-shd volumio[793]: info: CoreCommandRouter::volumiosetSourceActiveno-source May 24 17:27:14 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 17:27:14 minidsp-shd volumio[793]: Cannot find translation for source Presets May 24 17:27:14 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioStop May 24 17:27:14 minidsp-shd volumio[793]: info: CoreStateMachine::stop May 24 17:27:14 minidsp-shd volumio[793]: info: CoreStateMachine::setConsumeUpdateService undefined May 24 17:27:14 minidsp-shd volumio[793]: info: Notifying Active Input {"trackType":"input","service":"inputs","title":"TOSLINK","disableUiControls":true,"albumart":"/albumart"} May 24 17:27:14 minidsp-shd volumio[793]: info: CoreStateMachine::setConsumeUpdateService undefined May 24 17:27:14 minidsp-shd sudo[1217]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth/* May 24 17:27:14 minidsp-shd sudo[1217]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:14 minidsp-shd volumiobt[1215]: /bin/chmod: cannot access '/var/lib/bluetooth/*': No such file or directory May 24 17:27:14 minidsp-shd sudo[1217]: pam_unix(sudo:session): session closed for user root May 24 17:27:14 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:14+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 24 17:27:14 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:14+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 24 17:27:14 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:14+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 24 17:27:14 minidsp-shd volumio[793]: info: Volumio BT Module successfully started May 24 17:27:14 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:14+02:00" level=debug msg="zeroconf server listening on port 32777" May 24 17:27:14 minidsp-shd volumio[793]: info: Starting Shairport Sync May 24 17:27:14 minidsp-shd volumio[793]: info: Starting Shairport Sync May 24 17:27:14 minidsp-shd volumio[793]: info: Starting Shairport Sync May 24 17:27:14 minidsp-shd sudo[1221]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 24 17:27:14 minidsp-shd sudo[1221]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:14 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:14+02:00" level=debug msg="obtained new client token: AAA7JKUfr5lMKIY61adBFHl/vq2/QJLljK/W7m3d4VjIj6VQ7r8VSucnry0eZVaDl+WYHYVip208NEkrvb1xI9yaK2svck35M1J2fCcQF+O67JMbm1Ll8986sMzcEQzrtPeX0jBNr88zjNts9MkhMnnUFz86traHkwnsnbmb43+wA25pTL+zYjuS3WPCA45V+J90IFt/0lrUNYV4m8LMN5pAn54X9LJA8pz8bIUokm3VWMO9fj9h++1JMJmGzbY=" May 24 17:27:14 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable May 24 17:27:14 minidsp-shd sudo[1223]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 24 17:27:14 minidsp-shd sudo[1223]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:14 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:14+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" May 24 17:27:14 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 24 17:27:14 minidsp-shd sudo[1226]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 24 17:27:14 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. May 24 17:27:14 minidsp-shd sudo[1226]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:14 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 24 17:27:14 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:14+02:00" level=debug msg="completed keyexchange" May 24 17:27:14 minidsp-shd volumio[793]: xcb_connection_has_error() returned true May 24 17:27:14 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 24 17:27:14 minidsp-shd sudo[1223]: pam_unix(sudo:session): session closed for user root May 24 17:27:14 minidsp-shd sudo[1221]: pam_unix(sudo:session): session closed for user root May 24 17:27:14 minidsp-shd sudo[1232]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service May 24 17:27:14 minidsp-shd sudo[1232]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:14 minidsp-shd sudo[1226]: pam_unix(sudo:session): session closed for user root May 24 17:27:14 minidsp-shd volumio[793]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 24 17:27:14 minidsp-shd volumio[793]: SPOTIFY: BQAvNpZ0zT3RisSx_WkFJa8JB9-jwu-9xHtkZBg7aJhkeZqw7dBMPqHAyggsj6WQ4hftJ98FD3gWS3vkjsoJX39ESFyQo8Ez2MTW_k5cra43-FYYEbnhwGdDabZvoTCOj73uZTmzQu-bZ6U06FmZgsC4UFuLiTY1JUvu2PZVr4Uuu99ikDzfHnCmpk0YUquAS0Mgqc6XKgGhiJeuLngogb_eMHpKXrBvdvyHunLBh1LYK9HdHTZeFPTJuZgKiKFwFnlBxIcmDLigPrlRw5c312NlKKs May 24 17:27:14 minidsp-shd volumio[793]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 24 17:27:14 minidsp-shd volumio[793]: info: New Spotify access token = BQAvNpZ0zT3RisSx_WkFJa8JB9-jwu-9xHtkZBg7aJhkeZqw7dBMPqHAyggsj6WQ4hftJ98FD3gWS3vkjsoJX39ESFyQo8Ez2MTW_k5cra43-FYYEbnhwGdDabZvoTCOj73uZTmzQu-bZ6U06FmZgsC4UFuLiTY1JUvu2PZVr4Uuu99ikDzfHnCmpk0YUquAS0Mgqc6XKgGhiJeuLngogb_eMHpKXrBvdvyHunLBh1LYK9HdHTZeFPTJuZgKiKFwFnlBxIcmDLigPrlRw5c312NlKKs May 24 17:27:14 minidsp-shd volumio[793]: info: Spotify credentials grant success - running version from March 24, 2019 May 24 17:27:14 minidsp-shd volumio[793]: info: MRS: Found cast device: Altibox-TV-435455ce13cad7e711055c9a6762ab85 May 24 17:27:14 minidsp-shd volumio[793]: info: Adding audio output: May 24 17:27:14 minidsp-shd systemd[1]: Started RAAT DAEMON. May 24 17:27:14 minidsp-shd sudo[1232]: pam_unix(sudo:session): session closed for user root May 24 17:27:15 minidsp-shd volumio[793]: ------------------------------------ BT MESSAGE: BT STATUS: running May 24 17:27:15 minidsp-shd volumio[793]: ------------------------------------ BT MESSAGE: BT STATUS: waiting May 24 17:27:15 minidsp-shd volumio[793]: ------------------------------------ BT MESSAGE: BT STATUS: waiting May 24 17:27:15 minidsp-shd volumio[793]: ------------------------------------ BT MESSAGE: BT STATUS: waiting May 24 17:27:15 minidsp-shd volumio[793]: info: CoreCommandRouter::servicePushState May 24 17:27:15 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:15 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 17:27:15 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:15 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output update for this device May 24 17:27:15 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:15 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 24 17:27:15 minidsp-shd volumio[793]: info: Enabling external Volume Control May 24 17:27:15 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:15 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:15 minidsp-shd volumio[793]: info: MRS: Found cast device: Chromecast-Audio-4cae30823081f8544169b645ef26362c May 24 17:27:15 minidsp-shd volumio[793]: info: Adding audio output: May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="completed challenge" May 24 17:27:15 minidsp-shd volumio[793]: info: Raat Daemon started successfully May 24 17:27:15 minidsp-shd volumio[793]: info: Shairport-Sync Started May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="authenticated as 1164747946" May 24 17:27:15 minidsp-shd volumio[793]: Error adding Membership: Error: addMembership EINVAL May 24 17:27:15 minidsp-shd volumio[793]: info: Shairport-Sync Started May 24 17:27:15 minidsp-shd volumio[793]: info: Shairport-Sync Started May 24 17:27:15 minidsp-shd volumio[793]: info: TidalConnect service stoped! May 24 17:27:15 minidsp-shd sudo[1247]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall pulseaudio May 24 17:27:15 minidsp-shd sudo[1247]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:15 minidsp-shd volumiobt[1215]: pulseaudio: no process found May 24 17:27:15 minidsp-shd sudo[1247]: pam_unix(sudo:session): session closed for user root May 24 17:27:15 minidsp-shd volumio[793]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="authenticated as 1164747946" May 24 17:27:15 minidsp-shd dbus-daemon[466]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.18' (uid=1000 pid=1255 comm="/usr/bin/pulseaudio --high-priority=true ") May 24 17:27:15 minidsp-shd systemd[1]: Starting RealtimeKit Scheduling Policy Service... May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="dealer connection opened" May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="initializing zeroconf session, username: 1164747946" May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="received connection id: OTNjMmVlMmQtNzE2MC00NGU2LThjMTgtNTM4Njk0MjAwOTQ2K2RlYWxlcit0Y3A6Ly8wYWNhNWE1OS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNzgyNTMwRDdERTgxODlENzc2NjExMTdGQzE2QTQ2NDQxMUE3OEYxMDk1RDU1RTY5RkUzQjVGOUZFOUI5NjREMw==" May 24 17:27:15 minidsp-shd volumio[793]: info: Executing endpoint restartRAATSocket May 24 17:27:15 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="skipping dealer message" uri="ap://product-state-update" May 24 17:27:15 minidsp-shd dbus-daemon[466]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1' May 24 17:27:15 minidsp-shd systemd[1]: Started RealtimeKit Scheduling Policy Service. May 24 17:27:15 minidsp-shd rtkit-daemon[1256]: Successfully called chroot. May 24 17:27:15 minidsp-shd rtkit-daemon[1256]: Successfully dropped privileges. May 24 17:27:15 minidsp-shd rtkit-daemon[1256]: Successfully limited resources. May 24 17:27:15 minidsp-shd rtkit-daemon[1256]: Running. May 24 17:27:15 minidsp-shd rtkit-daemon[1256]: Canary thread running. May 24 17:27:15 minidsp-shd rtkit-daemon[1256]: Watchdog thread running. May 24 17:27:15 minidsp-shd dbus-daemon[466]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.19' (uid=0 pid=1256 comm="/usr/lib/rtkit/rtkit-daemon ") May 24 17:27:15 minidsp-shd systemd[1]: Starting Authorization Manager... May 24 17:27:15 minidsp-shd volumio[793]: ------------------------------------ BT MESSAGE: BT STATUS: running May 24 17:27:15 minidsp-shd volumio[793]: ------------------------------------ BT MESSAGE: BT STATUS: running May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="put connect state because NEW_DEVICE" May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="autoplay enabled: false" May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 24 17:27:15 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:15+02:00" level=debug msg="autoplay enabled: false" May 24 17:27:15 minidsp-shd polkitd[1261]: started daemon version 0.105 using authority implementation `local' version `0.105' May 24 17:27:16 minidsp-shd dbus-daemon[466]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' May 24 17:27:16 minidsp-shd systemd[1]: Started Authorization Manager. May 24 17:27:16 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioGetState May 24 17:27:16 minidsp-shd volumio[793]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 24 17:27:16 minidsp-shd volumio[793]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect May 24 17:27:16 minidsp-shd sudo[1270]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 24 17:27:16 minidsp-shd sudo[1270]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:16 minidsp-shd volumio[793]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 3 May 24 17:27:16 minidsp-shd volumio[793]: info: msSurfaceDial volumioupdatevolume callback: {"vol":78,"dbVolume":-28,"mute":false,"disableVolumeControl":false} May 24 17:27:16 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:16 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 17:27:16 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:16 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output update for this device May 24 17:27:16 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:16 minidsp-shd volumio[793]: error: Help! Some callbacks for volumioPushState are crashing! May 24 17:27:16 minidsp-shd systemd[1]: Started Volumio Tidal Connect Service. May 24 17:27:16 minidsp-shd volumio[793]: error: Cannot read property 'sendVolumeMute' of undefined May 24 17:27:16 minidsp-shd sudo[1270]: pam_unix(sudo:session): session closed for user root May 24 17:27:16 minidsp-shd volumio[793]: info: MRS: Getting audio outputs on start May 24 17:27:16 minidsp-shd volumio[793]: info: MRS: Requesting all other devices output May 24 17:27:16 minidsp-shd volumio[793]: info: go-librespot daemon successfully initialized May 24 17:27:17 minidsp-shd volumio[793]: SPOTIFY: User informations: {"country":"NO","display_name":"Bartek Gołędowski","email":"baltona84@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/1164747946"},"followers":{"href":null,"total":16},"href":"https://api.spotify.com/v1/users/1164747946","id":"1164747946","images":[{"height":300,"url":"https://scontent-bru2-1.xx.fbcdn.net/v/t39.30808-1/468740207_10163603388614369_2448924313253529105_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=107&ccb=1-7&_nc_sid=79bf43&_nc_ohc=tURqrmoVRPMQ7kNvwGLVn-D&_nc_oc=Adlu9IUxvmUdscY4Qj8f9C38HLRfCdsTzfNc1ABGMjVD_51y0E-B1GBFTUrNZuCJeQDyuRfXRaf6_WOidrmFBrv3&_nc_zt=24&_nc_ht=scontent-bru2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=9JuC69A0QCBeMOH48AarJA&oh=00_AfLUS9YthTrPYKajBdAU_qq_QIa4456YXdtyojpADr1ktw&oe=68378FEA","width":300},{"height":64,"url":"https://scontent-bru2-1.xx.fbcdn.net/v/t39.30808-1/468740207_10163603388614369_2448924313253529105_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=107&ccb=1-7&_nc_sid=28885b&_nc_ohc=tURqrmoVRPMQ7kNvwGLVn-D&_nc_oc=Adlu9IUxvmUdscY4Qj8f9C38HLRfCdsTzfNc1ABGMjVD_51y0E-B1GBFTUrNZuCJeQDyuRfXRaf6_WOidrmFBrv3&_nc_zt=24&_nc_ht=scontent-bru2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=9JuC69A0QCBeMOH48AarJA&oh=00_AfI5HWeG1eW2Nw3ruLPW8osVVp16QsbeClPCN6Jfz-r-gQ&oe=68378FEA","width":64}],"product":"premium","type":"user","uri":"spotify:user:1164747946"} May 24 17:27:17 minidsp-shd volumio[793]: info: Spotify Successfully logged in May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 24 17:27:17 minidsp-shd volumio[793]: info: [1748100437033] CoreMusicLibrary::Adding element Spotify May 24 17:27:17 minidsp-shd pulseaudio[1255]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 May 24 17:27:17 minidsp-shd pulseaudio[1255]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 May 24 17:27:17 minidsp-shd volumiobt[1215]: Applying permissions May 24 17:27:17 minidsp-shd volumiobt[1215]: Setting BT discoverable and pairable May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 17:27:17 minidsp-shd volumio[793]: Cannot find translation for source Presets May 24 17:27:17 minidsp-shd volumio[793]: Cannot find translation for source Spotify May 24 17:27:17 minidsp-shd pulseaudio[1255]: Failed to register as a handsfree audio agent with ofono: org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files May 24 17:27:17 minidsp-shd volumiobt[1215]: [38B blob data] May 24 17:27:17 minidsp-shd volumiobt[1215]: Invalid command May 24 17:27:17 minidsp-shd volumiobt[1215]: [bluetooth]# agent on May 24 17:27:17 minidsp-shd volumiobt[1215]: [bluetooth]# discoverable on May 24 17:27:17 minidsp-shd volumiobt[1215]: No default controller available May 24 17:27:17 minidsp-shd volumiobt[1215]: [bluetooth]# pairable on May 24 17:27:17 minidsp-shd volumiobt[1215]: No default controller available May 24 17:27:17 minidsp-shd volumiobt[1215]: [bluetooth]# agent NoInputNoOutput May 24 17:27:17 minidsp-shd volumiobt[1215]: Failed to register agent object May 24 17:27:17 minidsp-shd volumiobt[1215]: [bluetooth]# default-agent May 24 17:27:17 minidsp-shd volumiobt[1215]: No agent is registered May 24 17:27:17 minidsp-shd volumiobt[1215]: [bluetooth]# quit May 24 17:27:17 minidsp-shd volumiobt[1215]: [61B blob data] May 24 17:27:17 minidsp-shd volumiobt[1215]: [62B blob data] May 24 17:27:17 minidsp-shd volumio[793]: info: msSurfaceDial volumioupdatevolume callback: {"vol":78,"dbVolume":-28,"mute":false,"disableVolumeControl":false} May 24 17:27:17 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:17 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output update for this device May 24 17:27:17 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:17 minidsp-shd volumio[793]: error: Help! Some callbacks for volumioPushState are crashing! May 24 17:27:17 minidsp-shd volumio[793]: error: Cannot read property 'sendVolumeMute' of undefined May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioGetState May 24 17:27:17 minidsp-shd volumio[793]: info: Executing endpoint tc_getconfig May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig May 24 17:27:17 minidsp-shd vtcs[1272]: STARTING TidalConnect services, version: 1.3.0.19 May 24 17:27:17 minidsp-shd vtcs[1272]: STARTED TidalConnect services. May 24 17:27:17 minidsp-shd volumio[793]: info: Executing endpoint tc_connect May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect May 24 17:27:17 minidsp-shd volumio[793]: info: Connecting to TidalConnect May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::servicePushState May 24 17:27:17 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:17 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output update for this device May 24 17:27:17 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:17 minidsp-shd volumio[793]: info: CorePlayQueue::getTrack 0 May 24 17:27:17 minidsp-shd volumio[793]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} May 24 17:27:17 minidsp-shd volumio[793]: verbose: CURRENT POSITION 0 May 24 17:27:17 minidsp-shd volumio[793]: info: CoreStateMachine::syncState stateService stop May 24 17:27:17 minidsp-shd volumio[793]: info: CoreStateMachine::syncState currentStatus play May 24 17:27:17 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:17 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output update for this device May 24 17:27:17 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:18 minidsp-shd volumio[793]: info: CoreStateMachine::stPlaybackTimer May 24 17:27:18 minidsp-shd volumio[793]: info: CoreCommandRouter::servicePushState May 24 17:27:18 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:18 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 17:27:18 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:18 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output update for this device May 24 17:27:18 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:18 minidsp-shd volumio[793]: info: CorePlayQueue::getTrack 0 May 24 17:27:18 minidsp-shd volumio[793]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} May 24 17:27:18 minidsp-shd volumio[793]: verbose: CURRENT POSITION 0 May 24 17:27:18 minidsp-shd volumio[793]: info: CoreStateMachine::syncState stateService stop May 24 17:27:18 minidsp-shd volumio[793]: info: CoreStateMachine::syncState currentStatus stop May 24 17:27:18 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:18 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:18 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output update for this device May 24 17:27:18 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:18 minidsp-shd volumio[793]: info: No code May 24 17:27:18 minidsp-shd volumio[793]: info: CoreStateMachine::pushState May 24 17:27:18 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioPushState May 24 17:27:18 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output update for this device May 24 17:27:18 minidsp-shd volumio[793]: info: MRS: Pushing multiroomSync output May 24 17:27:19 minidsp-shd mpd[1109]: May 24 17:27 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 24 17:27:19 minidsp-shd systemd[1]: Started Music Player Daemon. May 24 17:27:19 minidsp-shd volumio[793]: Upnp client error: Error: This socket has been ended by the other party May 24 17:27:19 minidsp-shd sudo[1104]: pam_unix(sudo:session): session closed for user root May 24 17:27:19 minidsp-shd sudo[1093]: pam_unix(sudo:session): session closed for user root May 24 17:27:19 minidsp-shd volumio[793]: Upnp client error: Error: This socket has been ended by the other party May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=debug msg="handling transfer player command from 85757369114ddcc12e2aecd4fe342a061bb73c6b" May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=debug msg="resolved context of track" uri="spotify:artist:4O71i7ke5iIBX6RNSFoZbS" May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:artist:4O71i7ke5iIBX6RNSFoZbS" May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=trace msg="fetched new page 1 with 42 items (list: 52)" uri="spotify:artist:4O71i7ke5iIBX6RNSFoZbS" May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=debug msg="loading track (paused: true, position: 102078ms)" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:19 minidsp-shd volumio[793]: info: TidalConnect service started! May 24 17:27:19 minidsp-shd volumio[793]: info: Completed starting Core Plugins May 24 17:27:19 minidsp-shd volumio[793]: info: ------------------------------------------- May 24 17:27:19 minidsp-shd volumio[793]: info: ----- MyVolumio plugins startup ---- May 24 17:27:19 minidsp-shd volumio[793]: info: ------------------------------------------- May 24 17:27:19 minidsp-shd volumio[793]: info: [MyVolumio PluginManager] Fetching plans data.... May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=trace msg="emitting websocket event: will_play" May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 24 17:27:19 minidsp-shd volumio-remote-updater[460]: [2025-05-24 17:27:19] [connect] Successful connection May 24 17:27:19 minidsp-shd volumio[793]: error: MPD error: The expression evaluated to a falsy value: May 24 17:27:19 minidsp-shd volumio[793]: assert.ok(self.idling) May 24 17:27:19 minidsp-shd volumio[793]: error: The expression evaluated to a falsy value: May 24 17:27:19 minidsp-shd volumio[793]: assert.ok(self.idling) May 24 17:27:19 minidsp-shd volumio[793]: info: MPD running with PID1109 May 24 17:27:19 minidsp-shd volumio[793]: ,establishing connection May 24 17:27:19 minidsp-shd volumio[793]: error: updateQueue error: null May 24 17:27:19 minidsp-shd volumio-remote-updater[460]: [2025-05-24 17:27:19] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748100439 101 May 24 17:27:19 minidsp-shd volumio[793]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 4 May 24 17:27:19 minidsp-shd volumio[793]: error: updateQueue error: null May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=debug msg="selected format OGG_VORBIS_320 (bc8172e40e55a6b87fa758bce6b6dee78a163ae6)" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=debug msg="requested aes key for file bc8172e40e55a6b87fa758bce6b6dee78a163ae6, gid: 5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:19 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:19+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3202" May 24 17:27:19 minidsp-shd volumio[793]: info: Initializing connection to go-librespot Websocket May 24 17:27:20 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:20+02:00" level=debug msg="new websocket client" May 24 17:27:20 minidsp-shd volumio[793]: info: Connection to go-librespot Websocket established May 24 17:27:20 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:20+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2047" May 24 17:27:20 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:20+02:00" level=debug msg="fetched first chunk of 19, total size is 9781780 bytes" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:20 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:20+02:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:20 minidsp-shd volumio[1091]: Generating RSA private key, 4096 bit long modulus (2 primes) May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="fetched chunk 9/18, size: 524288" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="fetched chunk 10/18, size: 524288" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="fetched chunk 8/18, size: 524288" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="fetched chunk 7/18, size: 524288" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=trace msg="seek to 102078ms (diff: 127ms, samples: 4501639, bytes: 3801501)" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:21 minidsp-shd go-librespot[1191]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:257:(_snd_pcm_volumioswitch_hw_params) PCM volumioMultiRoomServer has buffer size 22050, but target_pcm volumioOutput has buffer size 4096 May 24 17:27:21 minidsp-shd go-librespot[1191]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:268:(_snd_pcm_volumioswitch_hw_params) PCM volumioMultiRoomServer has buffer size 22050, but target_pcm volumioOutput has buffer size 4096 May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="created new output device" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=info msg="loaded track \"Miss You\" (paused: true, position: 102078ms, duration: 247817ms, prefetched: false)" uri="spotify:track:5FE9EjOf2QaIEN74PxSJM7" May 24 17:27:21 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:21 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:21 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 24 17:27:21 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 24 17:27:21 minidsp-shd volumio[793]: info: Not Reporting Auto name since its the default one May 24 17:27:21 minidsp-shd volumio[793]: info: RAAT Overriding default device vendor model May 24 17:27:21 minidsp-shd volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=trace msg="emitting websocket event: metadata" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=trace msg="emitting websocket event: active" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="sending successful reply for dealer request" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="autoplay enabled: false" May 24 17:27:21 minidsp-shd volumio[793]: xcb_connection_has_error() returned true May 24 17:27:21 minidsp-shd volumio[793]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5FE9EjOf2QaIEN74PxSJM7","name":"Miss You","artist_names":["trentemøller"],"album_name":"The Last Resort","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0212467d7cca4ad137bbf16b43","position":102078,"duration":247817,"release_date":"year:2006 month:10 day:6","track_number":13,"disc_number":1}} May 24 17:27:21 minidsp-shd volumio[793]: SPOTIFY: received: {"type":"active","data":null} May 24 17:27:21 minidsp-shd volumio[793]: info: Aligning Spotify Volume to Volumio Volume May 24 17:27:21 minidsp-shd volumio[793]: info: CoreCommandRouter::volumioGetState May 24 17:27:21 minidsp-shd volumio[793]: info: Setting Spotify Volume from Volumio: 78 May 24 17:27:21 minidsp-shd sudo[1320]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service May 24 17:27:21 minidsp-shd sudo[1320]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=trace msg="emitting websocket event: paused" May 24 17:27:21 minidsp-shd go-librespot[1191]: time="2025-05-24T17:27:21+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 24 17:27:21 minidsp-shd systemd[1]: Stopping RAAT DAEMON... May 24 17:27:21 minidsp-shd systemd[1]: raat-daemon.service: Main process exited, code=killed, status=15/TERM May 24 17:27:21 minidsp-shd systemd[1]: raat-daemon.service: Succeeded. May 24 17:27:21 minidsp-shd systemd[1]: Stopped RAAT DAEMON. May 24 17:27:21 minidsp-shd volumio[793]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5FE9EjOf2QaIEN74PxSJM7","play_origin":"free-tier-artist"}} May 24 17:27:21 minidsp-shd volumio[793]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 24 17:27:21 minidsp-shd volumio[793]: TypeError: Cannot read property 'service' of undefined May 24 17:27:21 minidsp-shd volumio[793]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) May 24 17:27:21 minidsp-shd volumio[793]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) May 24 17:27:21 minidsp-shd volumio[793]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) May 24 17:27:21 minidsp-shd volumio[793]: at WebSocket.emit (events.js:400:28) May 24 17:27:21 minidsp-shd volumio[793]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 24 17:27:21 minidsp-shd volumio[793]: at Receiver.emit (events.js:400:28) May 24 17:27:21 minidsp-shd volumio[793]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 24 17:27:21 minidsp-shd volumio[793]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 24 17:27:21 minidsp-shd volumio[793]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 24 17:27:21 minidsp-shd volumio[793]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 24 17:27:21 minidsp-shd volumio[793]: at writeOrBuffer (internal/streams/writable.js:358:12) May 24 17:27:21 minidsp-shd volumio[793]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 24 17:27:21 minidsp-shd volumio[793]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 24 17:27:21 minidsp-shd volumio[793]: at Socket.emit (events.js:400:28) May 24 17:27:21 minidsp-shd volumio[793]: at addChunk (internal/streams/readable.js:293:12) May 24 17:27:21 minidsp-shd volumio[793]: at readableAddChunk (internal/streams/readable.js:267:9) May 24 17:27:21 minidsp-shd volumio[793]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 24 17:27:21 minidsp-shd systemd[1]: Started RAAT DAEMON. May 24 17:27:21 minidsp-shd sudo[1320]: pam_unix(sudo:session): session closed for user root May 24 17:27:22 minidsp-shd sudo[1342]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-24 17:26 May 24 17:27:22 minidsp-shd sudo[1342]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="17fcb754ddd6bd152b01008c46cc4ba1ca48bf35" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="281cefcd7a302aa7cfba569185cf7aae19b8c376" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="minidspshd" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 22 Mar 2024 03:13:25 PM CET" VOLUMIO_VERSION="3.608" VOLUMIO_HARDWARE="nanopineo3" VOLUMIO_DEVICENAME="Nanopi Neo3" VOLUMIO_VENDOR="miniDSP" VOLUMIO_MODEL="SHD" VOLUMIO_VENDOR_MODEL="miniDSP SHD" VOLUMIO_HASH="18533ba33f8f92d7e7e459bb30f70beb"