-- Logs begin at Fri 2024-03-22 15:13:25 CET, end at Sat 2024-10-19 09:28:01 CEST. -- Oct 19 09:27:16 minidsp-shd systemd[1]: Starting Daily apt download activities... Oct 19 09:27:18 minidsp-shd volumio-remote-updater[457]: [2024-10-19 09:27:18] [connect] Successful connection Oct 19 09:27:18 minidsp-shd systemd[1]: apt-daily.service: Succeeded. Oct 19 09:27:18 minidsp-shd systemd[1]: Started Daily apt download activities. Oct 19 09:27:18 minidsp-shd systemd[1]: Starting Daily apt upgrade and clean activities... Oct 19 09:27:18 minidsp-shd volumio[783]: info: Loading plugin "network"... Oct 19 09:27:18 minidsp-shd volumio[783]: info: Refreshing Cached IP Addresses Oct 19 09:27:18 minidsp-shd sudo[898]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 19 09:27:18 minidsp-shd sudo[898]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:18 minidsp-shd volumio[783]: info: Loading plugin "services"... Oct 19 09:27:18 minidsp-shd sudo[902]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 19 09:27:18 minidsp-shd sudo[898]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:18 minidsp-shd sudo[902]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:18 minidsp-shd volumio[783]: info: Loading plugin "alsa_controller"... Oct 19 09:27:18 minidsp-shd sudo[902]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:18 minidsp-shd sudo[905]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 19 09:27:18 minidsp-shd sudo[905]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:18 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 19 09:27:18 minidsp-shd volumio[783]: info: Loading plugin "wizard"... Oct 19 09:27:18 minidsp-shd volumio[783]: info: Loading plugin "networkfs"... Oct 19 09:27:19 minidsp-shd volumio[783]: info: Starting Udev Watcher for removable devices Oct 19 09:27:19 minidsp-shd sudo[924]: 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 Oct 19 09:27:19 minidsp-shd sudo[924]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:19 minidsp-shd kernel: FS-Cache: Loaded Oct 19 09:27:19 minidsp-shd volumio[783]: info: Ignoring mount for partition: BOOT Oct 19 09:27:19 minidsp-shd volumio[783]: info: Ignoring mount for partition: volumio Oct 19 09:27:19 minidsp-shd volumio[783]: info: Ignoring mount for partition: volumio_data Oct 19 09:27:19 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 19 09:27:19 minidsp-shd volumio[783]: info: Loading plugin "volumio_command_line_client"... Oct 19 09:27:19 minidsp-shd volumio[783]: info: Loading plugin "upnp"... Oct 19 09:27:19 minidsp-shd kernel: FS-Cache: Netfs 'cifs' registered for caching Oct 19 09:27:19 minidsp-shd kernel: Key type cifs.spnego registered Oct 19 09:27:19 minidsp-shd kernel: Key type cifs.idmap registered Oct 19 09:27:19 minidsp-shd kernel: CIFS: Attempting to mount //192.168.10.197/USB Oct 19 09:27:19 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. Oct 19 09:27:19 minidsp-shd volumio[783]: info: [1729322839265] Starting Upmpd Daemon Oct 19 09:27:19 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 19 09:27:19 minidsp-shd volumio[783]: info: Loading plugin "my_music"... Oct 19 09:27:19 minidsp-shd volumio[783]: info: Loading plugin "mpd"... Oct 19 09:27:19 minidsp-shd sudo[924]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:19 minidsp-shd systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 19 09:27:19 minidsp-shd systemd[1]: Started Daily apt upgrade and clean activities. Oct 19 09:27:20 minidsp-shd volumio[783]: info: Loading plugin "upnp_browser"... Oct 19 09:27:20 minidsp-shd volumio[783]: info: Loading plugin "bluetooth"... Oct 19 09:27:21 minidsp-shd volumio[783]: info: [1729322841346] Starting BluetoothController Oct 19 09:27:21 minidsp-shd volumio[783]: info: Loading plugin "alarm-clock"... Oct 19 09:27:22 minidsp-shd volumio[783]: info: Loading plugin "manifestui"... Oct 19 09:27:22 minidsp-shd volumio[783]: info: Loading plugin "metavolumio"... Oct 19 09:27:22 minidsp-shd sudo[905]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:23 minidsp-shd systemd[1]: systemd-fsckd.service: Succeeded. Oct 19 09:27:24 minidsp-shd sh[386]: timed out Oct 19 09:27:24 minidsp-shd dhcpcd[427]: timed out Oct 19 09:27:24 minidsp-shd sh[386]: dhcpcd exited Oct 19 09:27:24 minidsp-shd dhcpcd[427]: dhcpcd exited Oct 19 09:27:24 minidsp-shd sh[386]: ifup: failed to bring up eth0 Oct 19 09:27:24 minidsp-shd systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Oct 19 09:27:24 minidsp-shd systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Oct 19 09:27:24 minidsp-shd volumio[783]: info: Loading plugin "airplay_emulation"... Oct 19 09:27:24 minidsp-shd volumio[783]: info: Starting Shairport Sync Oct 19 09:27:24 minidsp-shd volumio[783]: info: Loading plugin "cd_controller"... Oct 19 09:27:25 minidsp-shd volumio[783]: info: Loading plugin "last_100"... Oct 19 09:27:25 minidsp-shd volumio[783]: info: Loading plugin "raat"... Oct 19 09:27:25 minidsp-shd volumio[783]: info: RAAT Plugin loaded Oct 19 09:27:25 minidsp-shd volumio[783]: info: Adding restartRAATSocket REST API Endpoint Oct 19 09:27:25 minidsp-shd volumio[783]: info: Adding restartRAATSocket REST Endpoint for plugin: music_service/raat Oct 19 09:27:25 minidsp-shd volumio[783]: info: Loading plugin "streaming_services"... Oct 19 09:27:28 minidsp-shd volumio[783]: info: Starting Streaming Service Transparent Proxy Oct 19 09:27:28 minidsp-shd volumio[783]: info: Loading plugin "tidalconnect"... Oct 19 09:27:28 minidsp-shd volumio[783]: info: Loading plugin "webradio"... Oct 19 09:27:28 minidsp-shd volumio[783]: info: Loading plugin "i2s_dacs"... Oct 19 09:27:28 minidsp-shd volumio[783]: info: I2S DAC not set, start Auto-detection Oct 19 09:27:28 minidsp-shd volumio[783]: info: Loading plugin "volumiodiscovery"... Oct 19 09:27:29 minidsp-shd volumio[783]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 19 09:27:29 minidsp-shd volumio[783]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 19 09:27:29 minidsp-shd node[783]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 19 09:27:29 minidsp-shd volumio[783]: *** WARNING *** For more information see Oct 19 09:27:29 minidsp-shd volumio[783]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 19 09:27:29 minidsp-shd volumio[783]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 19 09:27:29 minidsp-shd volumio[783]: *** WARNING *** For more information see Oct 19 09:27:29 minidsp-shd node[783]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 19 09:27:29 minidsp-shd node[783]: *** WARNING *** For more information see Oct 19 09:27:29 minidsp-shd node[783]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 19 09:27:29 minidsp-shd node[783]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 19 09:27:29 minidsp-shd node[783]: *** WARNING *** For more information see Oct 19 09:27:29 minidsp-shd volumio[783]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 19 09:27:29 minidsp-shd volumio[783]: info: Discovery: Started advertising with name: miniDSP SHD Oct 19 09:27:29 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 19 09:27:29 minidsp-shd volumio[783]: info: Loading plugin "spop"... Oct 19 09:27:30 minidsp-shd volumio[783]: STREAMING PROXY: Starting server on port 3245 Oct 19 09:27:30 minidsp-shd volumio[783]: Node JS runtime: 14 Oct 19 09:27:32 minidsp-shd volumio[783]: info: Loading plugin "multiroom"... Oct 19 09:27:33 minidsp-shd volumio-remote-updater[457]: [2024-10-19 09:27:33] [connect] Successful connection Oct 19 09:27:35 minidsp-shd volumio[783]: info: Applying required configuration parameters for plugin multiroom Oct 19 09:27:35 minidsp-shd sudo[978]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Oct 19 09:27:35 minidsp-shd sudo[978]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:35 minidsp-shd sudo[978]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:35 minidsp-shd volumio[783]: info: MRS: MultiRoom plugin initialized Oct 19 09:27:35 minidsp-shd volumio[783]: info: MRS: STOPPING SNAPCLIENT Oct 19 09:27:35 minidsp-shd volumio[783]: info: MRS: Snap server stop Oct 19 09:27:35 minidsp-shd sudo[994]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Oct 19 09:27:35 minidsp-shd sudo[994]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:35 minidsp-shd volumio[783]: info: MRS: STOPPING volumioStreaming Oct 19 09:27:35 minidsp-shd sudo[996]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Oct 19 09:27:35 minidsp-shd sudo[996]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:35 minidsp-shd sudo[994]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:35 minidsp-shd sudo[999]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Oct 19 09:27:35 minidsp-shd sudo[999]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:35 minidsp-shd volumio[783]: info: Loading plugin "outputs"... Oct 19 09:27:35 minidsp-shd sudo[1002]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Oct 19 09:27:35 minidsp-shd sudo[1002]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:35 minidsp-shd volumio[783]: info: Loading plugin "albumart"... Oct 19 09:27:35 minidsp-shd sudo[996]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:35 minidsp-shd sudo[1002]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:35 minidsp-shd sudo[999]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:35 minidsp-shd volumio[783]: info: Loading plugin "ms_surface_dial"... Oct 19 09:27:36 minidsp-shd volumio[783]: Forking 3 albumart workers Oct 19 09:27:36 minidsp-shd volumio[783]: info: Applying required configuration parameters for plugin ms_surface_dial Oct 19 09:27:36 minidsp-shd volumio[783]: info: Plugin example_plugin is not enabled Oct 19 09:27:36 minidsp-shd volumio[783]: info: Loading plugin "hi_res_audio"... Oct 19 09:27:38 minidsp-shd volumio[783]: Starting albumart workers Oct 19 09:27:38 minidsp-shd volumio[783]: Starting albumart workers Oct 19 09:27:38 minidsp-shd volumio[783]: Starting albumart workers Oct 19 09:27:39 minidsp-shd volumio[783]: info: Applying required configuration parameters for plugin hi_res_audio Oct 19 09:27:39 minidsp-shd volumio[783]: info: Loading plugin "inputs"... Oct 19 09:27:41 minidsp-shd volumio[783]: info: Loading plugin "qobuz"... Oct 19 09:27:43 minidsp-shd volumio[783]: info: Loading plugin "tidal"... Oct 19 09:27:46 minidsp-shd volumio[783]: info: Loading plugin "oem_helper"... Oct 19 09:27:48 minidsp-shd volumio-remote-updater[457]: [2024-10-19 09:27:48] [connect] Successful connection Oct 19 09:27:48 minidsp-shd volumio[783]: info: Applying required configuration parameters for plugin oem_helper Oct 19 09:27:48 minidsp-shd volumio[783]: info: Loading plugin "updater_comm"... Oct 19 09:27:48 minidsp-shd volumio[783]: info: Plugin mpdemulation is not enabled Oct 19 09:27:48 minidsp-shd volumio[783]: info: Loading plugin "rest_api"... Oct 19 09:27:48 minidsp-shd volumio[783]: info: Loading plugin "websocket"... Oct 19 09:27:48 minidsp-shd volumio[783]: info: Loading i18n strings for locale en Oct 19 09:27:48 minidsp-shd volumio[783]: Updating browse sources language Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::initPlayerControls Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 19 09:27:48 minidsp-shd volumio[783]: Express server listening on port 3000 Oct 19 09:27:48 minidsp-shd volumio[783]: [Metrics] WebUI: 37s 378.65ms Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreStateMachine::resetVolumioState Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreStateMachine::getcurrentVolume Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioRetrievevolume Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:49 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 09:27:49 minidsp-shd sudo[1067]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 19 09:27:49 minidsp-shd sudo[1067]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: inputs , getVolume Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: inputs , getDSP Oct 19 09:27:49 minidsp-shd sudo[1067]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:49 minidsp-shd sudo[1069]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 19 09:27:49 minidsp-shd sudo[1069]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:49 minidsp-shd sudo[1069]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:49 minidsp-shd volumio[783]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Oct 19 09:27:49 minidsp-shd volumio[783]: info: Completed loading Core Plugins Oct 19 09:27:49 minidsp-shd volumio[783]: info: Preparing to generate the ALSA configuration file Oct 19 09:27:49 minidsp-shd volumio[783]: info: Cannot read play queue from file Oct 19 09:27:49 minidsp-shd volumio[783]: info: MRS: Removed streaming files Oct 19 09:27:49 minidsp-shd volumio[783]: info: MRS: volumioStreaming STOPPED Oct 19 09:27:49 minidsp-shd volumio[783]: info: MRS: SNAPSERVER STOPPED Oct 19 09:27:49 minidsp-shd volumio[783]: info: MRS: SNAPCLIENT STOPPED Oct 19 09:27:49 minidsp-shd volumio[783]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision Oct 19 09:27:49 minidsp-shd volumio[783]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Oct 19 09:27:49 minidsp-shd volumio[783]: info: Reading ALSA contributions from plugins. Oct 19 09:27:49 minidsp-shd volumio-remote-updater[457]: [2024-10-19 09:27:49] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1729322868 101 Oct 19 09:27:49 minidsp-shd volumio[783]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreStateMachine::setRepeat null single undefined Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:49 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreStateMachine::setRandom null Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:49 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:49 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:49 minidsp-shd volumio[783]: info: Setting Device type: NanoPi NEO 3 Oct 19 09:27:50 minidsp-shd volumio[783]: info: Asound.conf file unchanged, so no further update is needed Oct 19 09:27:50 minidsp-shd volumio[783]: info: Output device has changed, restarting MPD Oct 19 09:27:50 minidsp-shd sudo[1078]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 19 09:27:50 minidsp-shd sudo[1078]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:50 minidsp-shd systemd[1]: Started UPnP Renderer front-end to MPD. Oct 19 09:27:50 minidsp-shd sudo[1081]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 19 09:27:50 minidsp-shd sudo[1081]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:50 minidsp-shd volumio[783]: info: Output device has changed, restarting Shairport Sync Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 09:27:50 minidsp-shd sudo[1081]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:50 minidsp-shd sudo[1078]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:50 minidsp-shd sudo[1085]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 19 09:27:50 minidsp-shd sudo[1085]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:50 minidsp-shd systemd[1]: Listening on mpd.socket. Oct 19 09:27:50 minidsp-shd volumio[783]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 19 09:27:50 minidsp-shd systemd[1]: Starting Music Player Daemon... Oct 19 09:27:50 minidsp-shd volumio[783]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:50 minidsp-shd volumio[783]: info: ___________ START PLUGINS ___________ Oct 19 09:27:50 minidsp-shd volumio[783]: info: ControllerMpd::onStart: Initializing MPD Oct 19 09:27:50 minidsp-shd volumio[783]: info: Creating MPD Configuration file Oct 19 09:27:50 minidsp-shd sudo[1094]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 19 09:27:50 minidsp-shd sudo[1094]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 19 09:27:50 minidsp-shd volumio[783]: info: [1729322870421] CoreMusicLibrary::Adding element Media Servers Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 09:27:50 minidsp-shd sudo[1094]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:50 minidsp-shd sudo[1096]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 19 09:27:50 minidsp-shd sudo[1096]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 19 09:27:50 minidsp-shd systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Oct 19 09:27:50 minidsp-shd systemd[1]: mpd.service: Succeeded. Oct 19 09:27:50 minidsp-shd systemd[1]: Stopped Music Player Daemon. Oct 19 09:27:50 minidsp-shd systemd[1]: Starting Music Player Daemon... Oct 19 09:27:50 minidsp-shd volumio[783]: info: Adding Manifest REST API Endpoints Oct 19 09:27:50 minidsp-shd volumio[783]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui Oct 19 09:27:50 minidsp-shd volumio[783]: info: Adding METAVOLUMIO REST API Endpoints Oct 19 09:27:50 minidsp-shd volumio[783]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Oct 19 09:27:50 minidsp-shd volumio[783]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Oct 19 09:27:50 minidsp-shd volumio[783]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Oct 19 09:27:50 minidsp-shd volumio[783]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 09:27:50 minidsp-shd sudo[1101]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name miniDSP SHD Oct 19 09:27:50 minidsp-shd sudo[1101]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:50 minidsp-shd sudo[1101]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:50 minidsp-shd volumio[783]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 09:27:50 minidsp-shd volumio[783]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 19 09:27:50 minidsp-shd volumio[783]: info: Preparing CD Folders Oct 19 09:27:50 minidsp-shd volumio[783]: info: Adding CD REST API Endpoints Oct 19 09:27:50 minidsp-shd volumio[783]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Oct 19 09:27:50 minidsp-shd volumio[783]: info: Starting UDEV Watcher for CD Oct 19 09:27:50 minidsp-shd volumio[783]: info: Detecting CD presence with UDEV Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 19 09:27:50 minidsp-shd volumio[783]: info: [1729322870831] CoreMusicLibrary::Adding element Last_100 Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 09:27:50 minidsp-shd volumio[783]: info: Starting RAAT Plugin Oct 19 09:27:50 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Oct 19 09:27:50 minidsp-shd volumio[783]: info: Additional UI Settings Added for plugin music_service/raat Oct 19 09:27:50 minidsp-shd volumio[783]: info: Streaming services startup Oct 19 09:27:50 minidsp-shd volumio[783]: info: Starting Streaming Daemon Oct 19 09:27:50 minidsp-shd sudo[1112]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 19 09:27:50 minidsp-shd sudo[1112]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:51 minidsp-shd sudo[1112]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:51 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 19 09:27:51 minidsp-shd volumio[783]: info: [1729322871087] CoreMusicLibrary::Adding element Webradio Oct 19 09:27:51 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 09:27:51 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 19 09:27:51 minidsp-shd sudo[1119]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 19 09:27:51 minidsp-shd sudo[1119]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:51 minidsp-shd volumio[783]: info: Creating Spotify config file Oct 19 09:27:51 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:51 minidsp-shd sudo[1119]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:51 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Oct 19 09:27:51 minidsp-shd volumio[783]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 19 09:27:51 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:51 minidsp-shd dbus-daemon[456]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.8' (uid=1000 pid=783 comm="/usr/bin/node /volumio/index.js ") Oct 19 09:27:51 minidsp-shd volumio[783]: error: Hi Res Audio Failed Login: Missing Login Data Oct 19 09:27:51 minidsp-shd volumio[783]: info: Adding HIGHRESAUDIO REST API Endpoints Oct 19 09:27:51 minidsp-shd volumio[783]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Oct 19 09:27:51 minidsp-shd systemd[1]: Starting Bluetooth service... Oct 19 09:27:51 minidsp-shd bluetoothd[1125]: Bluetooth daemon 5.23 Oct 19 09:27:51 minidsp-shd dbus-daemon[456]: [system] Successfully activated service 'org.bluez' Oct 19 09:27:51 minidsp-shd systemd[1]: Started Bluetooth service. Oct 19 09:27:51 minidsp-shd bluetoothd[1125]: Starting SDP server Oct 19 09:27:51 minidsp-shd bluetoothd[1125]: kernel lacks bnep-protocol support Oct 19 09:27:51 minidsp-shd bluetoothd[1125]: System does not support network plugin Oct 19 09:27:51 minidsp-shd dbus-daemon[456]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.11' (uid=0 pid=1125 comm="/usr/local/libexec/bluetooth/bluetoothd ") Oct 19 09:27:51 minidsp-shd bluetoothd[1125]: Bluetooth management interface 1.14 initialized Oct 19 09:27:51 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 19 09:27:51 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 09:27:51 minidsp-shd volumio[783]: info: Volumio Calling Home Oct 19 09:27:51 minidsp-shd systemd[1]: Starting Hostname Service... Oct 19 09:27:52 minidsp-shd volumio[783]: info: Stopping AccessToken refresher cron for QOBUZ Oct 19 09:27:52 minidsp-shd dbus-daemon[456]: [system] Successfully activated service 'org.freedesktop.hostname1' Oct 19 09:27:52 minidsp-shd systemd[1]: Started Hostname Service. Oct 19 09:27:52 minidsp-shd volumio[783]: info: AccessToken refresher cron started for QOBUZ Oct 19 09:27:52 minidsp-shd volumio[783]: info: Stopping AccessToken refresher cron Oct 19 09:27:52 minidsp-shd volumio[783]: info: AccessToken refresher cron started Oct 19 09:27:52 minidsp-shd volumio[783]: info: Adding TIDAL REST API Endpoints Oct 19 09:27:52 minidsp-shd volumio[783]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal Oct 19 09:27:52 minidsp-shd volumio[783]: info: Adding QOBUZ REST API Endpoints Oct 19 09:27:52 minidsp-shd volumio[783]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz Oct 19 09:27:52 minidsp-shd volumio[783]: info: Discovery: adding 7de2fe78-6056-4e2f-9f1b-de3300fc121e Oct 19 09:27:52 minidsp-shd volumio[783]: info: Discovery: Found device miniDSP SHD Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioGetState Oct 19 09:27:52 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:52 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output for this device Oct 19 09:27:52 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:52 minidsp-shd volumio[783]: info: Adding audio output: Oct 19 09:27:52 minidsp-shd volumio[783]: info: Adding audio output: Oct 19 09:27:52 minidsp-shd volumio[783]: info: Serial port opened successfully Oct 19 09:27:52 minidsp-shd volumio[783]: error: Cannot start Volumio Streaming Daemon Oct 19 09:27:52 minidsp-shd volumio[783]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 19 09:27:52 minidsp-shd volumio[783]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 19 09:27:52 minidsp-shd volumio[783]: info: RAAT Albumart path created successfully Oct 19 09:27:52 minidsp-shd volumio[783]: error: Cannot set new Bluetooth Name : Error: Command failed: /usr/bin/sudo /bin/hciconfig hci0 name 'miniDSP SHD' Oct 19 09:27:52 minidsp-shd volumio[783]: Can't get device info: No such device Oct 19 09:27:52 minidsp-shd volumio[783]: info: MPD Permissions set Oct 19 09:27:52 minidsp-shd volumio[783]: info: MPD Permissions set Oct 19 09:27:52 minidsp-shd volumio[783]: info: Upmpdcli Daemon Started Oct 19 09:27:52 minidsp-shd volumio[783]: info: msSurfaceDial volumioupdatevolume callback: {"vol":75,"dbVolume":-32,"disableVolumeControl":false} Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:52 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:52 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output update for this device Oct 19 09:27:52 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume Oct 19 09:27:52 minidsp-shd volumio[783]: info: Ignoring ROON Volume update because of undefined data Oct 19 09:27:52 minidsp-shd volumio[783]: info: msSurfaceDial Managed Objs {"/org/bluez":{"org.freedesktop.DBus.Introspectable":{},"org.bluez.AgentManager1":{},"org.bluez.ProfileManager1":{}}} Oct 19 09:27:52 minidsp-shd volumio[783]: info: [msSurfaceDial init()] check /org/bluez Oct 19 09:27:52 minidsp-shd volumio[783]: info: [msSurfaceDial init()] Adapter: null; SurfaceDial: null Oct 19 09:27:52 minidsp-shd volumio[783]: info: msSurfaceDial BluetoothSurfaceDial init() - ready! Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::Reload Ui Oct 19 09:27:52 minidsp-shd volumio[783]: info: Volumio called home Oct 19 09:27:52 minidsp-shd volumio[783]: info: Spotify config file written Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP Oct 19 09:27:52 minidsp-shd volumio[783]: info: updateDSP function in raat called! Oct 19 09:27:52 minidsp-shd volumio[783]: info: Updating RAAT Signal Path Oct 19 09:27:52 minidsp-shd volumio[783]: error: Cannot write to RAAT Client: TypeError: Cannot read property 'write' of undefined Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: raat , reconfigureAndRestartRaat Oct 19 09:27:52 minidsp-shd volumio[783]: info: Reconfiguring and Restarting RAAT Plugin Oct 19 09:27:52 minidsp-shd sudo[1142]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 19 09:27:52 minidsp-shd sudo[1142]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 19 09:27:52 minidsp-shd systemd[1]: Started go-librespot Daemon. Oct 19 09:27:52 minidsp-shd volumio[783]: info: Not Reporting Auto name since its the default one Oct 19 09:27:52 minidsp-shd volumio[783]: info: RAAT Overriding default device vendor model Oct 19 09:27:52 minidsp-shd volumio[783]: info: Adding MINIDSP Inputs Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 19 09:27:52 minidsp-shd volumio[783]: info: [1729322872868] CoreMusicLibrary::Adding element Inputs Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 09:27:52 minidsp-shd go-librespot[1148]: Librespot-go daemon starting... Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 19 09:27:52 minidsp-shd volumio[783]: info: [1729322872881] CoreMusicLibrary::Adding element Presets Oct 19 09:27:52 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 09:27:52 minidsp-shd volumio[783]: Cannot find translation for source Presets Oct 19 09:27:52 minidsp-shd sudo[1142]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:52 minidsp-shd volumio[783]: (node:783) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. Oct 19 09:27:52 minidsp-shd volumio[783]: (Use `node --trace-deprecation ...` to show where the warning was created) Oct 19 09:27:52 minidsp-shd volumio[783]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:53+02:00" level=info msg="generated new device id: db4609c5bb568bb4ed8114ed68b49e9d6b91b807" Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:53+02:00" level=debug msg="stored credentials found for 1164747946" Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:53 minidsp-shd volumio[783]: info: No need to fix Spotify hosts Oct 19 09:27:53 minidsp-shd sudo[1169]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Oct 19 09:27:53 minidsp-shd sudo[1169]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:53 minidsp-shd volumio[783]: info: Starting Shairport Sync Oct 19 09:27:53 minidsp-shd systemd[1]: Started Volumio Bluetooth Module. Oct 19 09:27:53 minidsp-shd volumio[783]: info: Starting Shairport Sync Oct 19 09:27:53 minidsp-shd sudo[1169]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:53 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:53+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 19 09:27:53 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:53+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 19 09:27:53 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:53+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 19 09:27:53 minidsp-shd volumio[783]: info: Starting Shairport Sync Oct 19 09:27:53 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:53+02:00" level=debug msg="zeroconf server listening on port 33845" Oct 19 09:27:53 minidsp-shd sudo[1174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 19 09:27:53 minidsp-shd sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:53 minidsp-shd sudo[1176]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth/* Oct 19 09:27:53 minidsp-shd sudo[1176]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:53 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Oct 19 09:27:53 minidsp-shd sudo[1177]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 19 09:27:53 minidsp-shd sudo[1177]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:53 minidsp-shd volumiobt[1173]: /bin/chmod: cannot access '/var/lib/bluetooth/*': No such file or directory Oct 19 09:27:53 minidsp-shd sudo[1176]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:54 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 19 09:27:54 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Oct 19 09:27:54 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 19 09:27:54 minidsp-shd sudo[1181]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 19 09:27:54 minidsp-shd sudo[1181]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:54 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:54+02:00" level=debug msg="obtained new client token: AABbJckWQTBxD26XxG5PV2yJs8B+VyLy5aAqfMwwe/hfd7/Rj5aggIdNP704qhjO1MsOCYbgp/HQEoBFb0CjT1G6L5yvA1VwdDItJJf+7n81W7rEQwGiUlZkoKfHQ65ESyvwghgvOZLKC9USuA74qYjELdi+GRP8ki4X9TRFsGu4IGDE07zFaH0mnbkv+nph6+DO4a4uWKPNReqiuJ8MVVQrl0BNFb3UHBaOZ0Q0sQPEFR4RCthhohOAsTrD" Oct 19 09:27:54 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 19 09:27:54 minidsp-shd sudo[1174]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:54 minidsp-shd sudo[1177]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:54 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:54+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Oct 19 09:27:54 minidsp-shd volumio[783]: xcb_connection_has_error() returned true Oct 19 09:27:54 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 19 09:27:54 minidsp-shd systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Oct 19 09:27:54 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Oct 19 09:27:54 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 19 09:27:54 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:54+02:00" level=debug msg="completed keyexchange" Oct 19 09:27:54 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 19 09:27:54 minidsp-shd sudo[1181]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:54 minidsp-shd volumio[783]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 19 09:27:54 minidsp-shd volumio[783]: SPOTIFY: BQCiu7ZQ033jF0fgmlv54LJxZrAw7MQT3AkuzAEUY_ZFC1ZPg_i0j0-KmQIo6KQx3JDUh7Sb9-XPMJWx4ni5T7KUsJEKW_W5Ok2sdghscanx8z0VtNiPLERN7Pj9BZ2xlkuy8LXRPDdoGSng6He51iX6dJ_x2fZmYrT0x8UNU8Plf6NWN33gfof_TxRGcGIfwKePLVU7v5lUHrO0vzDNGiw5xDVmQMB4ZOtcPeqYKNLi4acU2hD-_06Y6ho Oct 19 09:27:54 minidsp-shd volumio[783]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 19 09:27:54 minidsp-shd volumio[783]: info: New Spotify access token = BQCiu7ZQ033jF0fgmlv54LJxZrAw7MQT3AkuzAEUY_ZFC1ZPg_i0j0-KmQIo6KQx3JDUh7Sb9-XPMJWx4ni5T7KUsJEKW_W5Ok2sdghscanx8z0VtNiPLERN7Pj9BZ2xlkuy8LXRPDdoGSng6He51iX6dJ_x2fZmYrT0x8UNU8Plf6NWN33gfof_TxRGcGIfwKePLVU7v5lUHrO0vzDNGiw5xDVmQMB4ZOtcPeqYKNLi4acU2hD-_06Y6ho Oct 19 09:27:54 minidsp-shd volumio[783]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 19 09:27:54 minidsp-shd sudo[1190]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Oct 19 09:27:54 minidsp-shd sudo[1190]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:54 minidsp-shd volumio[783]: info: CoreCommandRouter::volumiosetSourceActiveno-source Oct 19 09:27:54 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 09:27:54 minidsp-shd volumio[783]: Cannot find translation for source Presets Oct 19 09:27:54 minidsp-shd systemd[1]: Started RAAT DAEMON. Oct 19 09:27:54 minidsp-shd sudo[1190]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:54 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:54+02:00" level=debug msg="completed challenge" Oct 19 09:27:54 minidsp-shd volumio[783]: info: Raat Daemon started successfully Oct 19 09:27:54 minidsp-shd volumio[783]: info: Shairport-Sync Started Oct 19 09:27:54 minidsp-shd volumio[783]: Error adding Membership: Error: addMembership EINVAL Oct 19 09:27:54 minidsp-shd volumio[783]: info: Shairport-Sync Started Oct 19 09:27:54 minidsp-shd volumio[783]: info: Shairport-Sync Started Oct 19 09:27:54 minidsp-shd volumio[783]: info: TidalConnect service stoped! Oct 19 09:27:54 minidsp-shd volumio[783]: info: Volumio BT Module successfully started Oct 19 09:27:54 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 19 09:27:54 minidsp-shd volumio[783]: info: Enabling external Volume Control Oct 19 09:27:54 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:54 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 19 09:27:54 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:54+02:00" level=debug msg="authenticated as 1164747946" Oct 19 09:27:54 minidsp-shd volumio[783]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 3 Oct 19 09:27:54 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:54+02:00" level=debug msg="authenticated as 1164747946" Oct 19 09:27:55 minidsp-shd volumio[783]: info: Executing endpoint restartRAATSocket Oct 19 09:27:55 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Oct 19 09:27:55 minidsp-shd sudo[1209]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall pulseaudio Oct 19 09:27:55 minidsp-shd sudo[1209]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="dealer connection opened" Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="initializing zeroconf session, username: 1164747946" Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="autoplay enabled: false" Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 19 09:27:55 minidsp-shd volumiobt[1173]: pulseaudio: no process found Oct 19 09:27:55 minidsp-shd sudo[1209]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="received connection id: ZTljYWY3YjctNzYxMC00ZTE4LWJhMzYtYTg2ZTUzNTc1MTY2K2RlYWxlcit0Y3A6Ly8wYWNhNTgzYy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArODNBOUJENkM0NEM1RUVCOTM2NjFBMkQxNjFGRkE3RUIxQUQzMEM0ODkyNDUzRkIzREFFQzU1NUI5QjQyOThGMw==" Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 495" Oct 19 09:27:55 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioGetState Oct 19 09:27:55 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:55 minidsp-shd dbus-daemon[456]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.17' (uid=1000 pid=1228 comm="/usr/bin/pulseaudio --high-priority=true ") Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Oct 19 09:27:55 minidsp-shd systemd[1]: Starting RealtimeKit Scheduling Policy Service... Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 19 09:27:55 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:55+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Oct 19 09:27:55 minidsp-shd dbus-daemon[456]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1' Oct 19 09:27:55 minidsp-shd systemd[1]: Started RealtimeKit Scheduling Policy Service. Oct 19 09:27:55 minidsp-shd rtkit-daemon[1233]: Successfully called chroot. Oct 19 09:27:55 minidsp-shd rtkit-daemon[1233]: Successfully dropped privileges. Oct 19 09:27:55 minidsp-shd rtkit-daemon[1233]: Successfully limited resources. Oct 19 09:27:55 minidsp-shd rtkit-daemon[1233]: Running. Oct 19 09:27:55 minidsp-shd dbus-daemon[456]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.18' (uid=0 pid=1233 comm="/usr/lib/rtkit/rtkit-daemon ") Oct 19 09:27:55 minidsp-shd rtkit-daemon[1233]: Canary thread running. Oct 19 09:27:55 minidsp-shd rtkit-daemon[1233]: Watchdog thread running. Oct 19 09:27:55 minidsp-shd volumio[783]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 19 09:27:55 minidsp-shd systemd[1]: Starting Authorization Manager... Oct 19 09:27:55 minidsp-shd volumio[783]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Oct 19 09:27:55 minidsp-shd volumio[783]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Oct 19 09:27:55 minidsp-shd polkitd[1247]: started daemon version 0.105 using authority implementation `local' version `0.105' Oct 19 09:27:55 minidsp-shd dbus-daemon[456]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' Oct 19 09:27:55 minidsp-shd systemd[1]: Started Authorization Manager. Oct 19 09:27:55 minidsp-shd volumio[783]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 19 09:27:55 minidsp-shd sudo[1262]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Oct 19 09:27:55 minidsp-shd sudo[1262]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 19 09:27:55 minidsp-shd volumio[783]: info: MRS: Found cast device: Altibox-TV-435455ce13cad7e711055c9a6762ab85 Oct 19 09:27:55 minidsp-shd volumio[783]: info: Adding audio output: Oct 19 09:27:55 minidsp-shd systemd[1]: Started Volumio Tidal Connect Service. Oct 19 09:27:55 minidsp-shd sudo[1262]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:55 minidsp-shd volumio[783]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 4 Oct 19 09:27:56 minidsp-shd volumio[783]: info: msSurfaceDial volumioupdatevolume callback: {"vol":75,"dbVolume":-32,"mute":false,"disableVolumeControl":false} Oct 19 09:27:56 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:56 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:56 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 19 09:27:56 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:56 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output update for this device Oct 19 09:27:56 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:56 minidsp-shd volumio[783]: error: Help! Some callbacks for volumioPushState are crashing! Oct 19 09:27:56 minidsp-shd volumio[783]: error: Cannot read property 'sendVolumeMute' of undefined Oct 19 09:27:56 minidsp-shd volumio[783]: info: MRS: Getting audio outputs on start Oct 19 09:27:56 minidsp-shd volumio[783]: info: MRS: Requesting all other devices output Oct 19 09:27:56 minidsp-shd volumio[783]: info: go-librespot daemon successfully initialized Oct 19 09:27:56 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioGetState Oct 19 09:27:56 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:56 minidsp-shd pulseaudio[1228]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Oct 19 09:27:56 minidsp-shd pulseaudio[1228]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Oct 19 09:27:56 minidsp-shd volumiobt[1173]: Applying permissions Oct 19 09:27:56 minidsp-shd volumiobt[1173]: Setting BT discoverable and pairable Oct 19 09:27:56 minidsp-shd pulseaudio[1228]: 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 Oct 19 09:27:56 minidsp-shd volumio[783]: 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-ams2-1.xx.fbcdn.net/v/t31.18172-1/27797538_10156432867544369_5035997697550006766_o.jpg?stp=dst-jpg_s320x320&_nc_cat=111&ccb=1-7&_nc_sid=05c18e&_nc_ohc=s5uTQFBntjkQ7kNvgFisafW&_nc_zt=24&_nc_ht=scontent-ams2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=ACWUpzlsTPBYIlvMJqgYFXG&oh=00_AYCYh1llIsoaQOkAw3NJ1-zP7d1h4KxtGA1Ltlz7poulAQ&oe=673A3CA3","width":300},{"height":64,"url":"https://scontent-ams2-1.xx.fbcdn.net/v/t31.18172-1/27797538_10156432867544369_5035997697550006766_o.jpg?stp=cp0_dst-jpg_s50x50&_nc_cat=111&ccb=1-7&_nc_sid=312bcd&_nc_ohc=s5uTQFBntjkQ7kNvgFisafW&_nc_zt=24&_nc_ht=scontent-ams2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=ACWUpzlsTPBYIlvMJqgYFXG&oh=00_AYBOaIcqlCL2tAWFxWnqbPn_ypwlYm3kVzywD7UHh1OO_Q&oe=673A3CA3","width":64}],"product":"premium","type":"user","uri":"spotify:user:1164747946"} Oct 19 09:27:56 minidsp-shd volumio[783]: info: Spotify Successfully logged in Oct 19 09:27:56 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 334" Oct 19 09:27:56 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:56+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 19 09:27:56 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 19 09:27:56 minidsp-shd volumio[783]: info: [1729322876860] CoreMusicLibrary::Adding element Spotify Oct 19 09:27:56 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 19 09:27:56 minidsp-shd volumio[783]: Cannot find translation for source Presets Oct 19 09:27:56 minidsp-shd volumiobt[1173]: [38B blob data] Oct 19 09:27:56 minidsp-shd volumiobt[1173]: Invalid command Oct 19 09:27:56 minidsp-shd volumiobt[1173]: [bluetooth]# agent on Oct 19 09:27:56 minidsp-shd volumio[783]: Cannot find translation for source Spotify Oct 19 09:27:56 minidsp-shd volumiobt[1173]: [bluetooth]# discoverable on Oct 19 09:27:56 minidsp-shd volumiobt[1173]: No default controller available Oct 19 09:27:56 minidsp-shd volumiobt[1173]: [bluetooth]# pairable on Oct 19 09:27:56 minidsp-shd volumiobt[1173]: No default controller available Oct 19 09:27:56 minidsp-shd volumiobt[1173]: [bluetooth]# agent NoInputNoOutput Oct 19 09:27:56 minidsp-shd volumiobt[1173]: Failed to register agent object Oct 19 09:27:56 minidsp-shd volumiobt[1173]: [bluetooth]# default-agent Oct 19 09:27:56 minidsp-shd volumiobt[1173]: No agent is registered Oct 19 09:27:56 minidsp-shd volumiobt[1173]: [bluetooth]# quit Oct 19 09:27:56 minidsp-shd volumiobt[1173]: [61B blob data] Oct 19 09:27:56 minidsp-shd volumiobt[1173]: [62B blob data] Oct 19 09:27:57 minidsp-shd volumio[783]: info: Executing endpoint tc_getconfig Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Oct 19 09:27:57 minidsp-shd vtcs[1264]: STARTING TidalConnect services, version: 1.3.0.19 Oct 19 09:27:57 minidsp-shd volumio[783]: info: msSurfaceDial volumioupdatevolume callback: {"vol":75,"dbVolume":-32,"mute":false,"disableVolumeControl":false} Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output update for this device Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:57 minidsp-shd volumio[783]: error: Help! Some callbacks for volumioPushState are crashing! Oct 19 09:27:57 minidsp-shd volumio[783]: error: Cannot read property 'sendVolumeMute' of undefined Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume Oct 19 09:27:57 minidsp-shd vtcs[1264]: STARTED TidalConnect services. Oct 19 09:27:57 minidsp-shd volumio[783]: info: Executing endpoint tc_connect Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Oct 19 09:27:57 minidsp-shd volumio[783]: info: Connecting to TidalConnect Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::servicePushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output update for this device Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:57 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:57 minidsp-shd volumio[783]: 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} Oct 19 09:27:57 minidsp-shd volumio[783]: verbose: CURRENT POSITION 0 Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::syncState stateService stop Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::syncState currentStatus stop Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output update for this device Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:57 minidsp-shd volumio[783]: info: No code Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output update for this device Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::servicePushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output update for this device Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:57 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:57 minidsp-shd volumio[783]: 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} Oct 19 09:27:57 minidsp-shd volumio[783]: verbose: CURRENT POSITION 0 Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::syncState stateService stop Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::syncState currentStatus stop Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output update for this device Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:57 minidsp-shd volumio[783]: info: No code Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreStateMachine::pushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:27:57 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioPushState Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output update for this device Oct 19 09:27:57 minidsp-shd volumio[783]: info: MRS: Pushing multiroomSync output Oct 19 09:27:58 minidsp-shd volumio[783]: info: TidalConnect service started! Oct 19 09:27:59 minidsp-shd mpd[1100]: Oct 19 09:27 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 19 09:27:59 minidsp-shd systemd[1]: Started Music Player Daemon. Oct 19 09:27:59 minidsp-shd volumio[783]: Upnp client error: Error: This socket has been ended by the other party Oct 19 09:27:59 minidsp-shd sudo[1096]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:59 minidsp-shd volumio[783]: Upnp client error: Error: This socket has been ended by the other party Oct 19 09:27:59 minidsp-shd sudo[1085]: pam_unix(sudo:session): session closed for user root Oct 19 09:27:59 minidsp-shd volumio[783]: info: Completed starting Core Plugins Oct 19 09:27:59 minidsp-shd volumio[783]: info: ------------------------------------------- Oct 19 09:27:59 minidsp-shd volumio[783]: info: ----- MyVolumio plugins startup ---- Oct 19 09:27:59 minidsp-shd volumio[783]: info: ------------------------------------------- Oct 19 09:27:59 minidsp-shd volumio[783]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 19 09:27:59 minidsp-shd volumio[783]: error: MPD error: The expression evaluated to a falsy value: Oct 19 09:27:59 minidsp-shd volumio[783]: assert.ok(self.idling) Oct 19 09:27:59 minidsp-shd volumio[783]: error: The expression evaluated to a falsy value: Oct 19 09:27:59 minidsp-shd volumio[783]: assert.ok(self.idling) Oct 19 09:27:59 minidsp-shd volumio[783]: info: MPD running with PID1100 Oct 19 09:27:59 minidsp-shd volumio[783]: ,establishing connection Oct 19 09:27:59 minidsp-shd volumio[783]: error: updateQueue error: null Oct 19 09:27:59 minidsp-shd volumio[783]: error: updateQueue error: null Oct 19 09:27:59 minidsp-shd volumio[783]: info: Initializing connection to go-librespot Websocket Oct 19 09:27:59 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:59+02:00" level=debug msg="new websocket client" Oct 19 09:27:59 minidsp-shd volumio[783]: info: Connection to go-librespot Websocket established Oct 19 09:27:59 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:59+02:00" level=debug msg="handling transfer player command from 1c3f961463532dd05c7fdd38b2200608ba8c3c1e" Oct 19 09:27:59 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:59+02:00" level=debug msg="resolved context of track" uri="spotify:artist:2AM4ilv6UzW0uMRuqKtDgN" Oct 19 09:27:59 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:59+02:00" level=trace msg="fetched new page 0 with 5 items (list: 5)" uri="spotify:artist:2AM4ilv6UzW0uMRuqKtDgN" Oct 19 09:27:59 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:59+02:00" level=trace msg="fetched new page 1 with 45 items (list: 50)" uri="spotify:artist:2AM4ilv6UzW0uMRuqKtDgN" Oct 19 09:27:59 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:59+02:00" level=debug msg="loading track (paused: false, position: 4655ms)" uri="spotify:track:0u6JFVn0KHHlidZxNL9gVE" Oct 19 09:27:59 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 19 09:27:59 minidsp-shd go-librespot[1148]: time="2024-10-19T09:27:59+02:00" level=trace msg="emitting websocket event: will_play" Oct 19 09:28:00 minidsp-shd volumio[783]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0u6JFVn0KHHlidZxNL9gVE","play_origin":"free-tier-artist"}} Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="selected format OGG_VORBIS_320 (5d391e1ba109ef555f0ce9b5ee363d3f4dc395d9)" uri="spotify:track:0u6JFVn0KHHlidZxNL9gVE" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="requested aes key for file 5d391e1ba109ef555f0ce9b5ee363d3f4dc395d9, gid: 0u6JFVn0KHHlidZxNL9gVE" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2822" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1867" Oct 19 09:28:00 minidsp-shd volumio[1083]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="fetched first chunk of 19, total size is 9627464 bytes" uri="spotify:track:0u6JFVn0KHHlidZxNL9gVE" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=trace msg="seek to 4655ms (diff: 161ms, samples: 205285, bytes: 174784)" uri="spotify:track:0u6JFVn0KHHlidZxNL9gVE" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:0u6JFVn0KHHlidZxNL9gVE" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: 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 Oct 19 09:28:00 minidsp-shd go-librespot[1148]: 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 Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="created new output device" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=info msg="loaded track \"La Grange (2005 Remaster)\" (paused: false, position: 4655ms, duration: 230480ms, prefetched: false)" uri="spotify:track:0u6JFVn0KHHlidZxNL9gVE" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=trace msg="scheduling prefetch in 196s" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=trace msg="emitting websocket event: metadata" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=trace msg="emitting websocket event: active" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="sending successful reply for dealer request" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 19 09:28:00 minidsp-shd volumio[783]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0u6JFVn0KHHlidZxNL9gVE","name":"La Grange (2005 Remaster)","artist_names":["ZZ Top"],"album_name":"Tres Hombres (Expanded 2006 Remaster)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02db9c5945ce3a3f873695d18a","position":4655,"duration":230480,"release_date":"year:1973 month:7 day:26","track_number":8,"disc_number":1}} Oct 19 09:28:00 minidsp-shd volumio[783]: SPOTIFY: received: {"type":"active","data":null} Oct 19 09:28:00 minidsp-shd volumio[783]: info: Aligning Spotify Volume to Volumio Volume Oct 19 09:28:00 minidsp-shd volumio[783]: info: CoreCommandRouter::volumioGetState Oct 19 09:28:00 minidsp-shd volumio[783]: info: CorePlayQueue::getTrack 0 Oct 19 09:28:00 minidsp-shd volumio[783]: info: Setting Spotify Volume from Volumio: 75 Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:0u6JFVn0KHHlidZxNL9gVE" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=trace msg="emitting websocket event: playing" Oct 19 09:28:00 minidsp-shd volumio[783]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0u6JFVn0KHHlidZxNL9gVE","play_origin":"free-tier-artist"}} Oct 19 09:28:00 minidsp-shd volumio[783]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 19 09:28:00 minidsp-shd go-librespot[1148]: time="2024-10-19T09:28:00+02:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:0u6JFVn0KHHlidZxNL9gVE" Oct 19 09:28:00 minidsp-shd volumio[783]: TypeError: Cannot read property 'service' of undefined Oct 19 09:28:00 minidsp-shd volumio[783]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Oct 19 09:28:00 minidsp-shd volumio[783]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Oct 19 09:28:00 minidsp-shd volumio[783]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Oct 19 09:28:00 minidsp-shd volumio[783]: at WebSocket.emit (events.js:400:28) Oct 19 09:28:00 minidsp-shd volumio[783]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 19 09:28:00 minidsp-shd volumio[783]: at Receiver.emit (events.js:400:28) Oct 19 09:28:00 minidsp-shd volumio[783]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 19 09:28:00 minidsp-shd volumio[783]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 19 09:28:00 minidsp-shd volumio[783]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 19 09:28:00 minidsp-shd volumio[783]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 19 09:28:00 minidsp-shd volumio[783]: at writeOrBuffer (internal/streams/writable.js:358:12) Oct 19 09:28:00 minidsp-shd volumio[783]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Oct 19 09:28:00 minidsp-shd volumio[783]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Oct 19 09:28:00 minidsp-shd volumio[783]: at Socket.emit (events.js:400:28) Oct 19 09:28:00 minidsp-shd volumio[783]: at addChunk (internal/streams/readable.js:293:12) Oct 19 09:28:00 minidsp-shd volumio[783]: at readableAddChunk (internal/streams/readable.js:267:9) Oct 19 09:28:00 minidsp-shd volumio[783]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 19 09:28:00 minidsp-shd volumio[1083]: ....++++ Oct 19 09:28:01 minidsp-shd sudo[1314]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-19 09:27 Oct 19 09:28:01 minidsp-shd sudo[1314]: 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"