-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sat 2025-05-17 08:00:37 CEST. -- May 17 07:59:53 minidsp-shd ntpd[786]: receive: Unexpected origin timestamp 0xeacc22b0.596b8608 does not match aorg 0000000000.00000000 from server@185.175.56.95 xmt 0xebd2a459.3e85168a May 17 07:59:53 minidsp-shd systemd[1]: Starting Daily apt download activities... May 17 07:59:53 minidsp-shd volumio[797]: info: Loading plugin "network"... May 17 07:59:53 minidsp-shd volumio[797]: info: Refreshing Cached IP Addresses May 17 07:59:53 minidsp-shd sudo[856]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 17 07:59:53 minidsp-shd sudo[856]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 07:59:53 minidsp-shd sh[387]: timed out May 17 07:59:53 minidsp-shd sh[387]: dhcpcd exited May 17 07:59:53 minidsp-shd dhcpcd[431]: timed out May 17 07:59:53 minidsp-shd systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 17 07:59:53 minidsp-shd sh[387]: ifup: failed to bring up eth0 May 17 07:59:53 minidsp-shd volumio[797]: info: Loading plugin "services"... May 17 07:59:53 minidsp-shd dhcpcd[431]: dhcpcd exited May 17 07:59:53 minidsp-shd systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 17 07:59:53 minidsp-shd sudo[859]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 17 07:59:53 minidsp-shd sudo[859]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 07:59:53 minidsp-shd sudo[856]: pam_unix(sudo:session): session closed for user root May 17 07:59:53 minidsp-shd volumio[797]: info: Loading plugin "alsa_controller"... May 17 07:59:53 minidsp-shd sudo[859]: pam_unix(sudo:session): session closed for user root May 17 07:59:53 minidsp-shd sudo[863]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 17 07:59:53 minidsp-shd sudo[863]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 07:59:54 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 17 07:59:54 minidsp-shd volumio[797]: info: Loading plugin "wizard"... May 17 07:59:54 minidsp-shd volumio[797]: info: Loading plugin "networkfs"... May 17 07:59:54 minidsp-shd volumio[797]: info: Starting Udev Watcher for removable devices May 17 07:59:54 minidsp-shd sudo[881]: 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 17 07:59:54 minidsp-shd sudo[881]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 07:59:54 minidsp-shd kernel: FS-Cache: Loaded May 17 07:59:54 minidsp-shd volumio[797]: info: Ignoring mount for partition: BOOT May 17 07:59:54 minidsp-shd volumio[797]: info: Ignoring mount for partition: volumio May 17 07:59:54 minidsp-shd volumio[797]: info: Ignoring mount for partition: volumio_data May 17 07:59:54 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 17 07:59:54 minidsp-shd volumio[797]: info: Loading plugin "volumio_command_line_client"... May 17 07:59:54 minidsp-shd volumio[797]: info: Loading plugin "upnp"... May 17 07:59:54 minidsp-shd kernel: FS-Cache: Netfs 'cifs' registered for caching May 17 07:59:54 minidsp-shd kernel: Key type cifs.spnego registered May 17 07:59:54 minidsp-shd kernel: Key type cifs.idmap registered May 17 07:59:54 minidsp-shd kernel: CIFS: Attempting to mount //192.168.10.197/USB May 17 07:59:54 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 17 07:59:54 minidsp-shd volumio[797]: info: [1747461594422] Starting Upmpd Daemon May 17 07:59:54 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 17 07:59:54 minidsp-shd volumio[797]: info: Loading plugin "my_music"... May 17 07:59:54 minidsp-shd volumio[797]: info: Loading plugin "mpd"... May 17 07:59:54 minidsp-shd sudo[881]: pam_unix(sudo:session): session closed for user root May 17 07:59:54 minidsp-shd systemd[1]: apt-daily.service: Succeeded. May 17 07:59:54 minidsp-shd systemd[1]: Started Daily apt download activities. May 17 07:59:54 minidsp-shd systemd[1]: Starting Daily apt upgrade and clean activities... May 17 07:59:55 minidsp-shd volumio[797]: info: Loading plugin "upnp_browser"... May 17 07:59:56 minidsp-shd systemd[1]: apt-daily-upgrade.service: Succeeded. May 17 07:59:56 minidsp-shd systemd[1]: Started Daily apt upgrade and clean activities. May 17 07:59:56 minidsp-shd volumio[797]: info: Loading plugin "bluetooth"... May 17 07:59:56 minidsp-shd volumio[797]: info: [1747461596652] Starting BluetoothController May 17 07:59:56 minidsp-shd volumio[797]: info: Loading plugin "alarm-clock"... May 17 07:59:57 minidsp-shd volumio[797]: info: Loading plugin "manifestui"... May 17 07:59:57 minidsp-shd volumio[797]: info: Loading plugin "metavolumio"... May 17 07:59:58 minidsp-shd sudo[863]: pam_unix(sudo:session): session closed for user root May 17 08:00:00 minidsp-shd volumio[797]: info: Loading plugin "airplay_emulation"... May 17 08:00:00 minidsp-shd volumio[797]: info: Starting Shairport Sync May 17 08:00:00 minidsp-shd volumio[797]: info: Loading plugin "cd_controller"... May 17 08:00:00 minidsp-shd volumio[797]: info: Loading plugin "last_100"... May 17 08:00:00 minidsp-shd volumio[797]: info: Loading plugin "raat"... May 17 08:00:01 minidsp-shd volumio[797]: info: RAAT Plugin loaded May 17 08:00:01 minidsp-shd volumio[797]: info: Adding restartRAATSocket REST API Endpoint May 17 08:00:01 minidsp-shd volumio[797]: info: Adding restartRAATSocket REST Endpoint for plugin: music_service/raat May 17 08:00:01 minidsp-shd volumio[797]: info: Loading plugin "streaming_services"... May 17 08:00:02 minidsp-shd volumio-remote-updater[467]: [2025-05-17 08:00:02] [connect] Successful connection May 17 08:00:03 minidsp-shd volumio[797]: info: Starting Streaming Service Transparent Proxy May 17 08:00:03 minidsp-shd volumio[797]: info: Loading plugin "tidalconnect"... May 17 08:00:03 minidsp-shd volumio[797]: info: Loading plugin "webradio"... May 17 08:00:04 minidsp-shd volumio[797]: info: Loading plugin "i2s_dacs"... May 17 08:00:04 minidsp-shd volumio[797]: info: I2S DAC not set, start Auto-detection May 17 08:00:04 minidsp-shd volumio[797]: info: Loading plugin "volumiodiscovery"... May 17 08:00:04 minidsp-shd volumio[797]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 17 08:00:04 minidsp-shd node[797]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 17 08:00:04 minidsp-shd node[797]: *** WARNING *** Please fix your application to use the native API of Avahi! May 17 08:00:04 minidsp-shd volumio[797]: *** WARNING *** Please fix your application to use the native API of Avahi! May 17 08:00:04 minidsp-shd volumio[797]: *** WARNING *** For more information see May 17 08:00:04 minidsp-shd volumio[797]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 17 08:00:04 minidsp-shd volumio[797]: *** WARNING *** Please fix your application to use the native API of Avahi! May 17 08:00:04 minidsp-shd volumio[797]: *** WARNING *** For more information see May 17 08:00:04 minidsp-shd node[797]: *** WARNING *** For more information see May 17 08:00:04 minidsp-shd node[797]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 17 08:00:04 minidsp-shd node[797]: *** WARNING *** Please fix your application to use the native API of Avahi! May 17 08:00:04 minidsp-shd node[797]: *** WARNING *** For more information see May 17 08:00:04 minidsp-shd volumio[797]: info: Applying required configuration parameters for plugin volumiodiscovery May 17 08:00:04 minidsp-shd volumio[797]: info: Discovery: Started advertising with name: miniDSP SHD May 17 08:00:04 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 17 08:00:04 minidsp-shd volumio[797]: info: Loading plugin "spop"... May 17 08:00:05 minidsp-shd volumio[797]: STREAMING PROXY: Starting server on port 3245 May 17 08:00:05 minidsp-shd volumio[797]: Node JS runtime: 14 May 17 08:00:07 minidsp-shd volumio[797]: info: Loading plugin "multiroom"... May 17 08:00:10 minidsp-shd volumio[797]: info: Applying required configuration parameters for plugin multiroom May 17 08:00:10 minidsp-shd sudo[992]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom May 17 08:00:10 minidsp-shd sudo[992]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:10 minidsp-shd sudo[992]: pam_unix(sudo:session): session closed for user root May 17 08:00:10 minidsp-shd volumio[797]: info: MRS: MultiRoom plugin initialized May 17 08:00:10 minidsp-shd volumio[797]: info: MRS: STOPPING SNAPCLIENT May 17 08:00:10 minidsp-shd volumio[797]: info: MRS: Snap server stop May 17 08:00:10 minidsp-shd sudo[1008]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient May 17 08:00:10 minidsp-shd volumio[797]: info: MRS: STOPPING volumioStreaming May 17 08:00:10 minidsp-shd sudo[1008]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:10 minidsp-shd sudo[1010]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver May 17 08:00:10 minidsp-shd sudo[1010]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:10 minidsp-shd volumio[797]: info: Loading plugin "outputs"... May 17 08:00:10 minidsp-shd sudo[1013]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming May 17 08:00:10 minidsp-shd sudo[1013]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:10 minidsp-shd sudo[1008]: pam_unix(sudo:session): session closed for user root May 17 08:00:10 minidsp-shd sudo[1016]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* May 17 08:00:10 minidsp-shd volumio[797]: info: Loading plugin "albumart"... May 17 08:00:10 minidsp-shd sudo[1016]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:10 minidsp-shd sudo[1016]: pam_unix(sudo:session): session closed for user root May 17 08:00:10 minidsp-shd sudo[1010]: pam_unix(sudo:session): session closed for user root May 17 08:00:10 minidsp-shd volumio[797]: info: Loading plugin "ms_surface_dial"... May 17 08:00:10 minidsp-shd sudo[1013]: pam_unix(sudo:session): session closed for user root May 17 08:00:11 minidsp-shd volumio[797]: Forking 3 albumart workers May 17 08:00:12 minidsp-shd volumio[797]: info: Applying required configuration parameters for plugin ms_surface_dial May 17 08:00:12 minidsp-shd volumio[797]: info: Plugin example_plugin is not enabled May 17 08:00:12 minidsp-shd volumio[797]: info: Loading plugin "hi_res_audio"... May 17 08:00:13 minidsp-shd volumio[797]: Starting albumart workers May 17 08:00:13 minidsp-shd volumio[797]: Starting albumart workers May 17 08:00:13 minidsp-shd volumio[797]: Starting albumart workers May 17 08:00:15 minidsp-shd volumio[797]: info: Applying required configuration parameters for plugin hi_res_audio May 17 08:00:15 minidsp-shd volumio[797]: info: Loading plugin "inputs"... May 17 08:00:16 minidsp-shd volumio[797]: info: Loading plugin "qobuz"... May 17 08:00:17 minidsp-shd volumio-remote-updater[467]: [2025-05-17 08:00:17] [connect] Successful connection May 17 08:00:19 minidsp-shd volumio[797]: info: Loading plugin "tidal"... May 17 08:00:21 minidsp-shd volumio[797]: info: Loading plugin "oem_helper"... May 17 08:00:23 minidsp-shd volumio[797]: info: Applying required configuration parameters for plugin oem_helper May 17 08:00:23 minidsp-shd volumio[797]: info: Loading plugin "updater_comm"... May 17 08:00:23 minidsp-shd volumio[797]: info: Plugin mpdemulation is not enabled May 17 08:00:23 minidsp-shd volumio[797]: info: Loading plugin "rest_api"... May 17 08:00:23 minidsp-shd volumio[797]: info: Loading plugin "websocket"... May 17 08:00:23 minidsp-shd volumio[797]: info: Loading i18n strings for locale en May 17 08:00:23 minidsp-shd volumio[797]: Updating browse sources language May 17 08:00:23 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::initPlayerControls May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 17 08:00:24 minidsp-shd volumio[797]: Express server listening on port 3000 May 17 08:00:24 minidsp-shd volumio[797]: [Metrics] WebUI: 37s 263.99ms May 17 08:00:24 minidsp-shd volumio[797]: info: CoreStateMachine::resetVolumioState May 17 08:00:24 minidsp-shd volumio[797]: info: CoreStateMachine::getcurrentVolume May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioRetrievevolume May 17 08:00:24 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:24 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 17 08:00:24 minidsp-shd sudo[1088]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 17 08:00:24 minidsp-shd sudo[1088]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: inputs , getVolume May 17 08:00:24 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: inputs , getDSP May 17 08:00:24 minidsp-shd sudo[1088]: pam_unix(sudo:session): session closed for user root May 17 08:00:24 minidsp-shd sudo[1096]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 17 08:00:24 minidsp-shd sudo[1096]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:24 minidsp-shd sudo[1096]: pam_unix(sudo:session): session closed for user root May 17 08:00:24 minidsp-shd volumio[797]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' May 17 08:00:24 minidsp-shd volumio[797]: info: Completed loading Core Plugins May 17 08:00:24 minidsp-shd volumio[797]: info: Preparing to generate the ALSA configuration file May 17 08:00:24 minidsp-shd volumio[797]: info: Cannot read play queue from file May 17 08:00:24 minidsp-shd volumio[797]: info: MRS: Removed streaming files May 17 08:00:24 minidsp-shd volumio[797]: info: MRS: volumioStreaming STOPPED May 17 08:00:24 minidsp-shd volumio[797]: info: MRS: SNAPSERVER STOPPED May 17 08:00:24 minidsp-shd volumio[797]: info: MRS: SNAPCLIENT STOPPED May 17 08:00:24 minidsp-shd volumio[797]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision May 17 08:00:24 minidsp-shd volumio[797]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf May 17 08:00:24 minidsp-shd volumio[797]: info: Reading ALSA contributions from plugins. May 17 08:00:25 minidsp-shd volumio[797]: info: CoreStateMachine::setRepeat false single undefined May 17 08:00:25 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:25 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:25 minidsp-shd volumio[797]: info: CoreStateMachine::setRandom null May 17 08:00:25 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:25 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:25 minidsp-shd volumio[797]: info: Setting Device type: NanoPi NEO 3 May 17 08:00:25 minidsp-shd volumio[797]: info: Asound.conf file unchanged, so no further update is needed May 17 08:00:25 minidsp-shd volumio[797]: info: Output device has changed, restarting MPD May 17 08:00:25 minidsp-shd sudo[1127]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 17 08:00:25 minidsp-shd sudo[1127]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:25 minidsp-shd systemd[1]: Started UPnP Renderer front-end to MPD. May 17 08:00:25 minidsp-shd sudo[1130]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 17 08:00:25 minidsp-shd sudo[1130]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:25 minidsp-shd volumio[797]: info: Output device has changed, restarting Shairport Sync May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 17 08:00:25 minidsp-shd sudo[1130]: pam_unix(sudo:session): session closed for user root May 17 08:00:25 minidsp-shd sudo[1127]: pam_unix(sudo:session): session closed for user root May 17 08:00:25 minidsp-shd sudo[1134]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 17 08:00:25 minidsp-shd sudo[1134]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:25 minidsp-shd volumio[797]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 17 08:00:25 minidsp-shd systemd[1]: Listening on mpd.socket. May 17 08:00:25 minidsp-shd volumio[797]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:25 minidsp-shd systemd[1]: Starting Music Player Daemon... May 17 08:00:25 minidsp-shd volumio[797]: info: ___________ START PLUGINS ___________ May 17 08:00:25 minidsp-shd volumio[797]: info: ControllerMpd::onStart: Initializing MPD May 17 08:00:25 minidsp-shd volumio[797]: info: Creating MPD Configuration file May 17 08:00:25 minidsp-shd sudo[1143]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 17 08:00:25 minidsp-shd sudo[1143]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 17 08:00:25 minidsp-shd volumio[797]: info: [1747461625826] CoreMusicLibrary::Adding element Media Servers May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 08:00:25 minidsp-shd sudo[1143]: pam_unix(sudo:session): session closed for user root May 17 08:00:25 minidsp-shd sudo[1145]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 17 08:00:25 minidsp-shd sudo[1145]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 17 08:00:25 minidsp-shd systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM May 17 08:00:25 minidsp-shd systemd[1]: mpd.service: Succeeded. May 17 08:00:25 minidsp-shd systemd[1]: Stopped Music Player Daemon. May 17 08:00:25 minidsp-shd systemd[1]: Starting Music Player Daemon... May 17 08:00:25 minidsp-shd volumio[797]: info: Adding Manifest REST API Endpoints May 17 08:00:25 minidsp-shd volumio[797]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui May 17 08:00:25 minidsp-shd volumio[797]: info: Adding METAVOLUMIO REST API Endpoints May 17 08:00:25 minidsp-shd volumio[797]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio May 17 08:00:25 minidsp-shd volumio[797]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio May 17 08:00:25 minidsp-shd volumio[797]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio May 17 08:00:25 minidsp-shd volumio[797]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:25 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 17 08:00:25 minidsp-shd sudo[1150]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name miniDSP SHD May 17 08:00:25 minidsp-shd sudo[1150]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:26 minidsp-shd sudo[1150]: pam_unix(sudo:session): session closed for user root May 17 08:00:26 minidsp-shd volumio[797]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 17 08:00:26 minidsp-shd volumio[797]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 17 08:00:26 minidsp-shd volumio[797]: info: Preparing CD Folders May 17 08:00:26 minidsp-shd volumio[797]: info: Adding CD REST API Endpoints May 17 08:00:26 minidsp-shd volumio[797]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller May 17 08:00:26 minidsp-shd volumio[797]: info: Starting UDEV Watcher for CD May 17 08:00:26 minidsp-shd volumio[797]: info: Detecting CD presence with UDEV May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 17 08:00:26 minidsp-shd volumio[797]: info: [1747461626225] CoreMusicLibrary::Adding element Last_100 May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 08:00:26 minidsp-shd volumio[797]: info: Starting RAAT Plugin May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections May 17 08:00:26 minidsp-shd volumio[797]: info: Additional UI Settings Added for plugin music_service/raat May 17 08:00:26 minidsp-shd volumio[797]: info: Streaming services startup May 17 08:00:26 minidsp-shd volumio[797]: info: Starting Streaming Daemon May 17 08:00:26 minidsp-shd sudo[1161]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 17 08:00:26 minidsp-shd sudo[1161]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:26 minidsp-shd sudo[1161]: pam_unix(sudo:session): session closed for user root May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 17 08:00:26 minidsp-shd volumio[797]: info: [1747461626475] CoreMusicLibrary::Adding element Webradio May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 17 08:00:26 minidsp-shd sudo[1168]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 17 08:00:26 minidsp-shd sudo[1168]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:26 minidsp-shd volumio[797]: info: Creating Spotify config file May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:26 minidsp-shd sudo[1168]: pam_unix(sudo:session): session closed for user root May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus May 17 08:00:26 minidsp-shd volumio[797]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration May 17 08:00:26 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:26 minidsp-shd dbus-daemon[474]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.8' (uid=1000 pid=797 comm="/usr/bin/node /volumio/index.js ") May 17 08:00:26 minidsp-shd volumio[797]: error: Hi Res Audio Failed Login: Missing Login Data May 17 08:00:26 minidsp-shd volumio[797]: info: Adding HIGHRESAUDIO REST API Endpoints May 17 08:00:26 minidsp-shd volumio[797]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio May 17 08:00:26 minidsp-shd systemd[1]: Starting Bluetooth service... May 17 08:00:26 minidsp-shd bluetoothd[1174]: Bluetooth daemon 5.23 May 17 08:00:27 minidsp-shd dbus-daemon[474]: [system] Successfully activated service 'org.bluez' May 17 08:00:27 minidsp-shd systemd[1]: Started Bluetooth service. May 17 08:00:27 minidsp-shd bluetoothd[1174]: Starting SDP server May 17 08:00:27 minidsp-shd bluetoothd[1174]: kernel lacks bnep-protocol support May 17 08:00:27 minidsp-shd bluetoothd[1174]: System does not support network plugin May 17 08:00:27 minidsp-shd bluetoothd[1174]: Bluetooth management interface 1.14 initialized May 17 08:00:27 minidsp-shd dbus-daemon[474]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.11' (uid=0 pid=1174 comm="/usr/local/libexec/bluetooth/bluetoothd ") May 17 08:00:27 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 17 08:00:27 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 17 08:00:27 minidsp-shd volumio[797]: info: Volumio Calling Home May 17 08:00:27 minidsp-shd systemd[1]: Starting Hostname Service... May 17 08:00:27 minidsp-shd volumio[797]: info: Stopping AccessToken refresher cron for QOBUZ May 17 08:00:27 minidsp-shd dbus-daemon[474]: [system] Successfully activated service 'org.freedesktop.hostname1' May 17 08:00:27 minidsp-shd systemd[1]: Started Hostname Service. May 17 08:00:27 minidsp-shd volumio[797]: info: AccessToken refresher cron started for QOBUZ May 17 08:00:27 minidsp-shd volumio[797]: info: Stopping AccessToken refresher cron May 17 08:00:27 minidsp-shd volumio[797]: info: AccessToken refresher cron started May 17 08:00:27 minidsp-shd volumio[797]: info: Adding TIDAL REST API Endpoints May 17 08:00:27 minidsp-shd volumio[797]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal May 17 08:00:27 minidsp-shd volumio[797]: info: Adding QOBUZ REST API Endpoints May 17 08:00:27 minidsp-shd volumio[797]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz May 17 08:00:27 minidsp-shd volumio[797]: info: Discovery: adding 7de2fe78-6056-4e2f-9f1b-de3300fc121e May 17 08:00:27 minidsp-shd volumio[797]: info: Discovery: Found device miniDSP SHD May 17 08:00:27 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioGetState May 17 08:00:27 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:27 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output for this device May 17 08:00:27 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:27 minidsp-shd volumio[797]: info: Adding audio output: May 17 08:00:27 minidsp-shd volumio[797]: info: Adding audio output: May 17 08:00:27 minidsp-shd volumio[797]: info: Serial port opened successfully May 17 08:00:27 minidsp-shd volumio[797]: error: Cannot start Volumio Streaming Daemon May 17 08:00:27 minidsp-shd volumio[797]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 17 08:00:27 minidsp-shd volumio[797]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 17 08:00:27 minidsp-shd volumio[797]: info: RAAT Albumart path created successfully May 17 08:00:27 minidsp-shd volumio[797]: error: Cannot set new Bluetooth Name : Error: Command failed: /usr/bin/sudo /bin/hciconfig hci0 name 'miniDSP SHD' May 17 08:00:27 minidsp-shd volumio[797]: Can't get device info: No such device May 17 08:00:27 minidsp-shd volumio[797]: info: MPD Permissions set May 17 08:00:27 minidsp-shd volumio[797]: info: MPD Permissions set May 17 08:00:27 minidsp-shd volumio[797]: info: Upmpdcli Daemon Started May 17 08:00:27 minidsp-shd volumio[797]: info: msSurfaceDial volumioupdatevolume callback: {"vol":83,"dbVolume":-22,"disableVolumeControl":false} May 17 08:00:27 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:27 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:27 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 08:00:27 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:27 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output update for this device May 17 08:00:27 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:27 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume May 17 08:00:28 minidsp-shd volumio[797]: info: Ignoring ROON Volume update because of undefined data May 17 08:00:28 minidsp-shd volumio[797]: info: msSurfaceDial Managed Objs {"/org/bluez":{"org.freedesktop.DBus.Introspectable":{},"org.bluez.AgentManager1":{},"org.bluez.ProfileManager1":{}}} May 17 08:00:28 minidsp-shd volumio[797]: info: [msSurfaceDial init()] check /org/bluez May 17 08:00:28 minidsp-shd volumio[797]: info: [msSurfaceDial init()] Adapter: null; SurfaceDial: null May 17 08:00:28 minidsp-shd volumio[797]: info: msSurfaceDial BluetoothSurfaceDial init() - ready! May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::Reload Ui May 17 08:00:28 minidsp-shd volumio[797]: info: Volumio called home May 17 08:00:28 minidsp-shd volumio[797]: info: Spotify config file written May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP May 17 08:00:28 minidsp-shd volumio[797]: info: updateDSP function in raat called! May 17 08:00:28 minidsp-shd volumio[797]: info: Updating RAAT Signal Path May 17 08:00:28 minidsp-shd volumio[797]: error: Cannot write to RAAT Client: TypeError: Cannot read property 'write' of undefined May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: raat , reconfigureAndRestartRaat May 17 08:00:28 minidsp-shd volumio[797]: info: Reconfiguring and Restarting RAAT Plugin May 17 08:00:28 minidsp-shd sudo[1191]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 17 08:00:28 minidsp-shd sudo[1191]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd systemd[1]: Started go-librespot Daemon. May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 17 08:00:28 minidsp-shd sudo[1191]: pam_unix(sudo:session): session closed for user root May 17 08:00:28 minidsp-shd volumio[797]: info: Not Reporting Auto name since its the default one May 17 08:00:28 minidsp-shd volumio[797]: info: RAAT Overriding default device vendor model May 17 08:00:28 minidsp-shd go-librespot[1197]: Librespot-go daemon starting... May 17 08:00:28 minidsp-shd volumio[797]: info: Adding MINIDSP Inputs May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 17 08:00:28 minidsp-shd volumio[797]: info: [1747461628263] CoreMusicLibrary::Adding element Inputs May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 17 08:00:28 minidsp-shd volumio[797]: info: [1747461628271] CoreMusicLibrary::Adding element Presets May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 08:00:28 minidsp-shd volumio[797]: Cannot find translation for source Presets May 17 08:00:28 minidsp-shd volumio[797]: (node:797) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. May 17 08:00:28 minidsp-shd volumio[797]: (Use `node --trace-deprecation ...` to show where the warning was created) May 17 08:00:28 minidsp-shd volumio[797]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 1 May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:28+02:00" level=info msg="generated new device id: f8978e956d4428d73f1aa1f230b242e05c400528" May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:28+02:00" level=debug msg="stored credentials found for 1164747946" May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber May 17 08:00:28 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:28 minidsp-shd volumio[797]: info: No need to fix Spotify hosts May 17 08:00:29 minidsp-shd sudo[1218]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service May 17 08:00:29 minidsp-shd sudo[1218]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:29 minidsp-shd volumio[797]: info: Starting Shairport Sync May 17 08:00:29 minidsp-shd systemd[1]: Started Volumio Bluetooth Module. May 17 08:00:29 minidsp-shd sudo[1218]: pam_unix(sudo:session): session closed for user root May 17 08:00:29 minidsp-shd volumio[797]: info: Starting Shairport Sync May 17 08:00:29 minidsp-shd volumio[797]: info: Starting Shairport Sync May 17 08:00:29 minidsp-shd sudo[1223]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth/* May 17 08:00:29 minidsp-shd sudo[1223]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:29 minidsp-shd sudo[1224]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 17 08:00:29 minidsp-shd sudo[1224]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:29 minidsp-shd volumiobt[1221]: /bin/chmod: cannot access '/var/lib/bluetooth/*': No such file or directory May 17 08:00:29 minidsp-shd sudo[1223]: pam_unix(sudo:session): session closed for user root May 17 08:00:29 minidsp-shd sudo[1226]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 17 08:00:29 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable May 17 08:00:29 minidsp-shd sudo[1226]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:29 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:29+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 17 08:00:29 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:29+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 17 08:00:29 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:29+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 17 08:00:29 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 17 08:00:29 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:29+02:00" level=debug msg="zeroconf server listening on port 42925" May 17 08:00:29 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. May 17 08:00:29 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 17 08:00:29 minidsp-shd sudo[1231]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 17 08:00:29 minidsp-shd sudo[1231]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:29 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 17 08:00:29 minidsp-shd sudo[1226]: pam_unix(sudo:session): session closed for user root May 17 08:00:29 minidsp-shd sudo[1224]: pam_unix(sudo:session): session closed for user root May 17 08:00:29 minidsp-shd volumio[797]: xcb_connection_has_error() returned true May 17 08:00:29 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 17 08:00:29 minidsp-shd systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 17 08:00:29 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. May 17 08:00:29 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 17 08:00:29 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 17 08:00:29 minidsp-shd sudo[1231]: pam_unix(sudo:session): session closed for user root May 17 08:00:29 minidsp-shd volumio[797]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 17 08:00:29 minidsp-shd volumio[797]: SPOTIFY: BQC_0d2AyFE2uIXnipLsLEnF-CtjS6ygc8DQ4XhZXhoe6_vmT7KO9fV8h1rc-g6fNOziAGjYoFDgzEHjC9M7MuKBBHD87r3Jw1QUggeuh2s8coLHuEdibq1LmyzNm1AfDjY9XD0SMV-Bq2EU0yPvw3znHy04HBTyC41LtyaaLIthorRKkZV8iDgbN4yoMUpGVPkmPICWua59NIferyIqRin6ailTd65yYD24ed-MefB0D9PcXwgQrexP2jvYMhwgjAjI1QQb8qhRIV8kZGoo_3_RAMA May 17 08:00:29 minidsp-shd volumio[797]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 17 08:00:29 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:29+02:00" level=debug msg="obtained new client token: AADQe7WNtOH//acRGg4PC0z+dnqI+FyYaDJHIfWSUEwxbbZLYm3sn5HiG5n/nEFDrTWgq/W71qzeL/2qEsrUwgDlR4gdNEXQADMxC01Y0yAVy+QGkwC678d6SoHP7dtHdH9w9yoVsLlxbLU74NijTWRCU0/ldpdqjr3s3NeMqfzNXTSN5OOBit4qsKOllsIGUny7FOUhSNDItE9OMZP0ZaKigT0rHlVh53RYUidYMRRE551seCl1nyl+FWq0A9E=" May 17 08:00:29 minidsp-shd volumio[797]: info: New Spotify access token = BQC_0d2AyFE2uIXnipLsLEnF-CtjS6ygc8DQ4XhZXhoe6_vmT7KO9fV8h1rc-g6fNOziAGjYoFDgzEHjC9M7MuKBBHD87r3Jw1QUggeuh2s8coLHuEdibq1LmyzNm1AfDjY9XD0SMV-Bq2EU0yPvw3znHy04HBTyC41LtyaaLIthorRKkZV8iDgbN4yoMUpGVPkmPICWua59NIferyIqRin6ailTd65yYD24ed-MefB0D9PcXwgQrexP2jvYMhwgjAjI1QQb8qhRIV8kZGoo_3_RAMA May 17 08:00:29 minidsp-shd volumio[797]: info: Spotify credentials grant success - running version from March 24, 2019 May 17 08:00:29 minidsp-shd sudo[1238]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service May 17 08:00:29 minidsp-shd sudo[1238]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:29 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:29+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" May 17 08:00:29 minidsp-shd volumio[797]: info: MRS: Found cast device: Altibox-TV-435455ce13cad7e711055c9a6762ab85 May 17 08:00:29 minidsp-shd volumio[797]: info: Adding audio output: May 17 08:00:29 minidsp-shd volumio[797]: info: CoreCommandRouter::volumiosetSourceActiveno-source May 17 08:00:29 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 08:00:29 minidsp-shd volumio[797]: Cannot find translation for source Presets May 17 08:00:29 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:29+02:00" level=debug msg="completed keyexchange" May 17 08:00:29 minidsp-shd systemd[1]: Started RAAT DAEMON. May 17 08:00:29 minidsp-shd sudo[1238]: pam_unix(sudo:session): session closed for user root May 17 08:00:30 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 17 08:00:30 minidsp-shd volumio[797]: info: Enabling external Volume Control May 17 08:00:30 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 17 08:00:30 minidsp-shd volumio[797]: info: Raat Daemon started successfully May 17 08:00:30 minidsp-shd volumio[797]: info: Shairport-Sync Started May 17 08:00:30 minidsp-shd volumio[797]: Error adding Membership: Error: addMembership EINVAL May 17 08:00:30 minidsp-shd volumio[797]: info: Shairport-Sync Started May 17 08:00:30 minidsp-shd volumio[797]: info: Shairport-Sync Started May 17 08:00:30 minidsp-shd volumio[797]: info: TidalConnect service stoped! May 17 08:00:30 minidsp-shd volumio[797]: info: Volumio BT Module successfully started May 17 08:00:30 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:30+02:00" level=debug msg="completed challenge" May 17 08:00:30 minidsp-shd volumio[797]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 May 17 08:00:30 minidsp-shd sudo[1257]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall pulseaudio May 17 08:00:30 minidsp-shd sudo[1257]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:30 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:30+02:00" level=debug msg="authenticated as 1164747946" May 17 08:00:30 minidsp-shd volumiobt[1221]: pulseaudio: no process found May 17 08:00:30 minidsp-shd sudo[1257]: pam_unix(sudo:session): session closed for user root May 17 08:00:30 minidsp-shd volumio[797]: info: Executing endpoint restartRAATSocket May 17 08:00:30 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection May 17 08:00:30 minidsp-shd dbus-daemon[474]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.17' (uid=1000 pid=1261 comm="/usr/bin/pulseaudio --high-priority=true ") May 17 08:00:30 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:30+02:00" level=debug msg="authenticated as 1164747946" May 17 08:00:30 minidsp-shd systemd[1]: Starting RealtimeKit Scheduling Policy Service... May 17 08:00:30 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioGetState May 17 08:00:30 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:30 minidsp-shd dbus-daemon[474]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1' May 17 08:00:30 minidsp-shd systemd[1]: Started RealtimeKit Scheduling Policy Service. May 17 08:00:30 minidsp-shd rtkit-daemon[1267]: Successfully called chroot. May 17 08:00:30 minidsp-shd rtkit-daemon[1267]: Successfully dropped privileges. May 17 08:00:30 minidsp-shd rtkit-daemon[1267]: Successfully limited resources. May 17 08:00:30 minidsp-shd rtkit-daemon[1267]: Running. May 17 08:00:30 minidsp-shd dbus-daemon[474]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.18' (uid=0 pid=1267 comm="/usr/lib/rtkit/rtkit-daemon ") May 17 08:00:30 minidsp-shd rtkit-daemon[1267]: Watchdog thread running. May 17 08:00:30 minidsp-shd rtkit-daemon[1267]: Canary thread running. May 17 08:00:30 minidsp-shd volumio[797]: ------------------------------------ BT MESSAGE: BT STATUS: running May 17 08:00:30 minidsp-shd systemd[1]: Starting Authorization Manager... May 17 08:00:30 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:30+02:00" level=debug msg="dealer connection opened" May 17 08:00:30 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:30+02:00" level=debug msg="initializing zeroconf session, username: 1164747946" May 17 08:00:30 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:30+02:00" level=debug msg="received connection id: ZjJmYmZlNmYtN2I2MS00ZWY3LTlhMjItMTA3ZmQ0ZjczYzVhK2RlYWxlcit0Y3A6Ly8wYWNhNTljNC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRUYwRTE3ODIwNkMzNDU2RkNGOTgxNEE5MTQyMTVGNTVDNzY2MDAwNDAwMUMwNDU2MDc2QTE3MDREMkQzOTAxMA==" May 17 08:00:30 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:30+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 17 08:00:30 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:30+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 17 08:00:30 minidsp-shd polkitd[1270]: started daemon version 0.105 using authority implementation `local' version `0.105' May 17 08:00:30 minidsp-shd dbus-daemon[474]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' May 17 08:00:30 minidsp-shd systemd[1]: Started Authorization Manager. May 17 08:00:31 minidsp-shd volumio[797]: ------------------------------------ BT MESSAGE: BT STATUS: running May 17 08:00:31 minidsp-shd volumio[797]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 17 08:00:31 minidsp-shd volumio[797]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect May 17 08:00:31 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:31+02:00" level=debug msg="put connect state because NEW_DEVICE" May 17 08:00:31 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:31+02:00" level=debug msg="autoplay enabled: false" May 17 08:00:31 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:31+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 17 08:00:31 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:31+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 17 08:00:31 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:31+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 17 08:00:31 minidsp-shd sudo[1275]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 17 08:00:31 minidsp-shd sudo[1275]: pam_unix(sudo:session): session opened for user root by (uid=0) May 17 08:00:31 minidsp-shd volumio[797]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 3 May 17 08:00:31 minidsp-shd volumio[797]: info: msSurfaceDial volumioupdatevolume callback: {"vol":83,"dbVolume":-22,"mute":false,"disableVolumeControl":false} May 17 08:00:31 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:31 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:31 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 08:00:31 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:31 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output update for this device May 17 08:00:31 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:31 minidsp-shd volumio[797]: error: Help! Some callbacks for volumioPushState are crashing! May 17 08:00:31 minidsp-shd volumio[797]: error: Cannot read property 'sendVolumeMute' of undefined May 17 08:00:31 minidsp-shd systemd[1]: Started Volumio Tidal Connect Service. May 17 08:00:31 minidsp-shd sudo[1275]: pam_unix(sudo:session): session closed for user root May 17 08:00:31 minidsp-shd volumio[797]: 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-mrs2-2.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=rKnI-6t-UhwQ7kNvwH-c1ZB&_nc_oc=AdkwnLR_2FiyXZjuTaVmllgu_IF3faGZq5rwEixpl0uM6yS1BPQLe6W6pyR2FFFYzhv-pwWdsSCk7dddXfKtIjxR&_nc_zt=24&_nc_ht=scontent-mrs2-2.xx&edm=AP4hL3IEAAAA&_nc_gid=BUWBz8LqSE67vfn6tXt55Q&oh=00_AfKBC-x4Ap62atBExSAEuGXOFCIVmDDBHVEe7X7rk1DU0g&oe=682D746A","width":300},{"height":64,"url":"https://scontent-mrs2-2.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=rKnI-6t-UhwQ7kNvwH-c1ZB&_nc_oc=AdkwnLR_2FiyXZjuTaVmllgu_IF3faGZq5rwEixpl0uM6yS1BPQLe6W6pyR2FFFYzhv-pwWdsSCk7dddXfKtIjxR&_nc_zt=24&_nc_ht=scontent-mrs2-2.xx&edm=AP4hL3IEAAAA&_nc_gid=BUWBz8LqSE67vfn6tXt55Q&oh=00_AfJ1MgP1vl7jP5GH6v9lmdj4DrQZA6SgcG3EzBQScjyjtg&oe=682D746A","width":64}],"product":"premium","type":"user","uri":"spotify:user:1164747946"} May 17 08:00:31 minidsp-shd volumio[797]: info: Spotify Successfully logged in May 17 08:00:31 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:31+02:00" level=debug msg="handling transfer player command from 85757369114ddcc12e2aecd4fe342a061bb73c6b" May 17 08:00:31 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 17 08:00:31 minidsp-shd volumio[797]: info: [1747461631805] CoreMusicLibrary::Adding element Spotify May 17 08:00:31 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 17 08:00:31 minidsp-shd volumio[797]: Cannot find translation for source Presets May 17 08:00:31 minidsp-shd volumio[797]: Cannot find translation for source Spotify May 17 08:00:31 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:31+02:00" level=debug msg="resolved context of track" uri="spotify:album:0LMCaTWQEcX80IFs0uUiLF" May 17 08:00:31 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:31+02:00" level=trace msg="fetched new page 0 with 25 items (list: 25)" uri="spotify:album:0LMCaTWQEcX80IFs0uUiLF" May 17 08:00:31 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:31+02:00" level=debug msg="loading track (paused: true, position: 73335ms)" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:32 minidsp-shd volumio[797]: info: MRS: Getting audio outputs on start May 17 08:00:32 minidsp-shd pulseaudio[1261]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 May 17 08:00:32 minidsp-shd pulseaudio[1261]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 May 17 08:00:32 minidsp-shd volumiobt[1221]: Applying permissions May 17 08:00:32 minidsp-shd volumiobt[1221]: Setting BT discoverable and pairable May 17 08:00:32 minidsp-shd volumio[797]: info: MRS: Requesting all other devices output May 17 08:00:32 minidsp-shd volumio[797]: info: go-librespot daemon successfully initialized May 17 08:00:32 minidsp-shd pulseaudio[1261]: 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 17 08:00:32 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 17 08:00:32 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:32+02:00" level=trace msg="emitting websocket event: will_play" May 17 08:00:32 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:32+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 17 08:00:32 minidsp-shd volumiobt[1221]: [38B blob data] May 17 08:00:32 minidsp-shd volumiobt[1221]: Invalid command May 17 08:00:32 minidsp-shd volumiobt[1221]: [bluetooth]# agent on May 17 08:00:32 minidsp-shd volumiobt[1221]: [bluetooth]# discoverable on May 17 08:00:32 minidsp-shd volumiobt[1221]: No default controller available May 17 08:00:32 minidsp-shd volumiobt[1221]: [bluetooth]# pairable on May 17 08:00:32 minidsp-shd volumiobt[1221]: No default controller available May 17 08:00:32 minidsp-shd volumiobt[1221]: [bluetooth]# agent NoInputNoOutput May 17 08:00:32 minidsp-shd volumiobt[1221]: Failed to register agent object May 17 08:00:32 minidsp-shd volumiobt[1221]: [bluetooth]# default-agent May 17 08:00:32 minidsp-shd volumiobt[1221]: No agent is registered May 17 08:00:32 minidsp-shd volumiobt[1221]: [bluetooth]# quit May 17 08:00:32 minidsp-shd volumiobt[1221]: [61B blob data] May 17 08:00:32 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:32+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3202" May 17 08:00:32 minidsp-shd volumiobt[1221]: [62B blob data] May 17 08:00:32 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:32+02:00" level=debug msg="selected format OGG_VORBIS_320 (c418cfb4cf0bd1dad179d6c8b59152cc9df86a7f)" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:32 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:32+02:00" level=debug msg="requested aes key for file c418cfb4cf0bd1dad179d6c8b59152cc9df86a7f, gid: 2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:32 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioGetState May 17 08:00:32 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:32 minidsp-shd volumio[797]: info: msSurfaceDial volumioupdatevolume callback: {"vol":83,"dbVolume":-22,"mute":false,"disableVolumeControl":false} May 17 08:00:32 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:32 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:32 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:32 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output update for this device May 17 08:00:32 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:32 minidsp-shd volumio[797]: error: Help! Some callbacks for volumioPushState are crashing! May 17 08:00:32 minidsp-shd volumio[797]: error: Cannot read property 'sendVolumeMute' of undefined May 17 08:00:32 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume May 17 08:00:32 minidsp-shd volumio[797]: info: Executing endpoint tc_getconfig May 17 08:00:32 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig May 17 08:00:32 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:32+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2047" May 17 08:00:32 minidsp-shd vtcs[1277]: STARTING TidalConnect services, version: 1.3.0.19 May 17 08:00:32 minidsp-shd volumio-remote-updater[467]: [2025-05-17 08:00:32] [connect] Successful connection May 17 08:00:32 minidsp-shd volumio-remote-updater[467]: [2025-05-17 08:00:32] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1747461632 101 May 17 08:00:32 minidsp-shd volumio[797]: 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 17 08:00:32 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:32+02:00" level=debug msg="fetched first chunk of 38, total size is 19788799 bytes" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:32 minidsp-shd vtcs[1277]: STARTED TidalConnect services. May 17 08:00:32 minidsp-shd volumio[797]: info: Executing endpoint tc_connect May 17 08:00:32 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect May 17 08:00:32 minidsp-shd volumio[797]: info: Connecting to TidalConnect May 17 08:00:33 minidsp-shd volumio[797]: info: CoreCommandRouter::servicePushState May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:33 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:33 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:33 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:33+02:00" level=debug msg="fetched chunk 1/37, size: 524288" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output update for this device May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:33 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:33 minidsp-shd volumio[797]: 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 17 08:00:33 minidsp-shd volumio[797]: verbose: CURRENT POSITION 0 May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::syncState stateService stop May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::syncState currentStatus stop May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:33 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:33 minidsp-shd volumio[797]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 17 08:00:33 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output update for this device May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:33 minidsp-shd volumio[797]: info: No code May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:33 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:33 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output update for this device May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:33 minidsp-shd volumio[797]: info: CoreCommandRouter::servicePushState May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:33 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:33 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output update for this device May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:33 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:33 minidsp-shd volumio[797]: 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 17 08:00:33 minidsp-shd volumio[797]: verbose: CURRENT POSITION 0 May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::syncState stateService stop May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::syncState currentStatus stop May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:33 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:33 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output update for this device May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:33 minidsp-shd volumio[797]: info: No code May 17 08:00:33 minidsp-shd volumio[797]: info: CoreStateMachine::pushState May 17 08:00:33 minidsp-shd volumio[797]: info: CorePlayQueue::getTrack 0 May 17 08:00:33 minidsp-shd volumio[797]: info: CoreCommandRouter::volumioPushState May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output update for this device May 17 08:00:33 minidsp-shd volumio[797]: info: MRS: Pushing multiroomSync output May 17 08:00:33 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:33+02:00" level=debug msg="fetched chunk 3/37, size: 524288" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="fetched chunk 9/37, size: 524288" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="fetched chunk 7/37, size: 524288" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="fetched chunk 2/37, size: 524288" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="fetched chunk 6/37, size: 524288" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=trace msg="seek to 73335ms (diff: 116ms, samples: 3234073, bytes: 3244828)" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="fetched chunk 8/37, size: 524288" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:34 minidsp-shd go-librespot[1197]: 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 17 08:00:34 minidsp-shd go-librespot[1197]: 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 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="created new output device" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=info msg="loaded track \"Time to Time\" (paused: true, position: 73335ms, duration: 450800ms, prefetched: false)" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=trace msg="emitting websocket event: metadata" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=trace msg="emitting websocket event: active" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="sending successful reply for dealer request" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 17 08:00:34 minidsp-shd volumio[797]: info: TidalConnect service started! May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=trace msg="emitting websocket event: paused" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="handling update_context player command from 85757369114ddcc12e2aecd4fe342a061bb73c6b" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 17 08:00:34 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:34+02:00" level=debug msg="sending successful reply for dealer request" May 17 08:00:35 minidsp-shd volumio[797]: info: Initializing connection to go-librespot Websocket May 17 08:00:35 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:35+02:00" level=debug msg="new websocket client" May 17 08:00:35 minidsp-shd volumio[797]: info: Connection to go-librespot Websocket established May 17 08:00:35 minidsp-shd mpd[1149]: May 17 08:00 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 17 08:00:35 minidsp-shd systemd[1]: Started Music Player Daemon. May 17 08:00:35 minidsp-shd volumio[797]: Upnp client error: Error: This socket has been ended by the other party May 17 08:00:35 minidsp-shd volumio[797]: Upnp client error: Error: This socket has been ended by the other party May 17 08:00:35 minidsp-shd sudo[1145]: pam_unix(sudo:session): session closed for user root May 17 08:00:35 minidsp-shd sudo[1134]: pam_unix(sudo:session): session closed for user root May 17 08:00:35 minidsp-shd volumio[797]: info: Completed starting Core Plugins May 17 08:00:35 minidsp-shd volumio[797]: info: ------------------------------------------- May 17 08:00:35 minidsp-shd volumio[797]: info: ----- MyVolumio plugins startup ---- May 17 08:00:35 minidsp-shd volumio[797]: info: ------------------------------------------- May 17 08:00:35 minidsp-shd volumio[797]: info: [MyVolumio PluginManager] Fetching plans data.... May 17 08:00:35 minidsp-shd volumio[797]: error: MPD error: The expression evaluated to a falsy value: May 17 08:00:35 minidsp-shd volumio[797]: assert.ok(self.idling) May 17 08:00:35 minidsp-shd volumio[797]: error: The expression evaluated to a falsy value: May 17 08:00:35 minidsp-shd volumio[797]: assert.ok(self.idling) May 17 08:00:35 minidsp-shd volumio[797]: info: MPD running with PID1149 May 17 08:00:35 minidsp-shd volumio[797]: ,establishing connection May 17 08:00:35 minidsp-shd volumio[797]: error: updateQueue error: null May 17 08:00:35 minidsp-shd volumio[797]: error: updateQueue error: null May 17 08:00:35 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:35+02:00" level=debug msg="handling resume player command from 85757369114ddcc12e2aecd4fe342a061bb73c6b" May 17 08:00:35 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:35+02:00" level=trace msg="seek to 73335ms (diff: 116ms, samples: 3234073, bytes: 3244828)" uri="spotify:track:2aoRsP1gwbb7bJ8V6ZMACP" May 17 08:00:35 minidsp-shd go-librespot[1197]: 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 17 08:00:35 minidsp-shd go-librespot[1197]: 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 17 08:00:35 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:35+02:00" level=debug msg="resume track at 73219ms" May 17 08:00:35 minidsp-shd volumio[1132]: Generating RSA private key, 4096 bit long modulus (2 primes) May 17 08:00:36 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 17 08:00:36 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:36+02:00" level=trace msg="scheduling prefetch in 347s" May 17 08:00:36 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:36+02:00" level=debug msg="sending successful reply for dealer request" May 17 08:00:36 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 17 08:00:36 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:36+02:00" level=trace msg="emitting websocket event: playing" May 17 08:00:36 minidsp-shd volumio[797]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2aoRsP1gwbb7bJ8V6ZMACP","play_origin":"playlist"}} May 17 08:00:36 minidsp-shd volumio[797]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 17 08:00:36 minidsp-shd volumio[797]: TypeError: Cannot read property 'service' of undefined May 17 08:00:36 minidsp-shd volumio[797]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) May 17 08:00:36 minidsp-shd volumio[797]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) May 17 08:00:36 minidsp-shd volumio[797]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) May 17 08:00:36 minidsp-shd volumio[797]: at WebSocket.emit (events.js:400:28) May 17 08:00:36 minidsp-shd volumio[797]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 17 08:00:36 minidsp-shd volumio[797]: at Receiver.emit (events.js:400:28) May 17 08:00:36 minidsp-shd volumio[797]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 17 08:00:36 minidsp-shd volumio[797]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 17 08:00:36 minidsp-shd volumio[797]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 17 08:00:36 minidsp-shd volumio[797]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 17 08:00:36 minidsp-shd volumio[797]: at writeOrBuffer (internal/streams/writable.js:358:12) May 17 08:00:36 minidsp-shd volumio[797]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 17 08:00:36 minidsp-shd volumio[797]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 17 08:00:36 minidsp-shd volumio[797]: at Socket.emit (events.js:400:28) May 17 08:00:36 minidsp-shd volumio[797]: at addChunk (internal/streams/readable.js:293:12) May 17 08:00:36 minidsp-shd volumio[797]: at readableAddChunk (internal/streams/readable.js:267:9) May 17 08:00:36 minidsp-shd volumio[797]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 17 08:00:37 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:37+02:00" level=debug msg="handling play player command from 85757369114ddcc12e2aecd4fe342a061bb73c6b" May 17 08:00:37 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:37+02:00" level=debug msg="resolved context of track" uri="spotify:album:0LMCaTWQEcX80IFs0uUiLF" May 17 08:00:37 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:37+02:00" level=trace msg="fetched new page 0 with 25 items (list: 25)" uri="spotify:album:0LMCaTWQEcX80IFs0uUiLF" May 17 08:00:37 minidsp-shd go-librespot[1197]: time="2025-05-17T08:00:37+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:2Ctn0QhA4oab2vkOXmNQZh" May 17 08:00:37 minidsp-shd sudo[1330]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-17 07:59 May 17 08:00:37 minidsp-shd sudo[1330]: 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"