-- Logs begin at Tue 2024-04-16 00:07:36 EDT, end at Fri 2024-05-03 15:00:44 EDT. -- May 03 15:00:14 minidsp-shd ntpd[950]: receive: Unexpected origin timestamp 0xe9c87821.58909632 does not match aorg 0000000000.00000000 from server@66.228.59.187 xmt 0xe9dfb2be.91e4c429 May 03 15:00:14 minidsp-shd systemd[1]: Starting Daily apt download activities... May 03 15:00:14 minidsp-shd ntpd[950]: receive: Unexpected origin timestamp 0xe9c87821.5889b5ae does not match aorg 0000000000.00000000 from server@104.167.241.253 xmt 0xe9dfb2be.941bdd5e May 03 15:00:14 minidsp-shd ntpd[950]: receive: Unexpected origin timestamp 0xe9c87821.588cbe17 does not match aorg 0000000000.00000000 from server@158.51.125.98 xmt 0xe9dfb2be.9478361c May 03 15:00:14 minidsp-shd ntpd[950]: receive: Unexpected origin timestamp 0xe9c87821.58924e6f does not match aorg 0000000000.00000000 from server@198.137.202.56 xmt 0xe9dfb2be.96f977f5 May 03 15:00:14 minidsp-shd ntpd[950]: receive: Unexpected origin timestamp 0xe9c87821.588e658f does not match aorg 0000000000.00000000 from server@155.248.196.28 xmt 0xe9dfb2be.975a7950 May 03 15:00:14 minidsp-shd volumio[956]: info: Loading plugin "bluetooth"... May 03 15:00:15 minidsp-shd volumio[956]: info: [1714762815127] Starting BluetoothController May 03 15:00:15 minidsp-shd volumio[956]: info: Loading plugin "alarm-clock"... May 03 15:00:15 minidsp-shd systemd[1]: apt-daily.service: Succeeded. May 03 15:00:15 minidsp-shd systemd[1]: Started Daily apt download activities. May 03 15:00:15 minidsp-shd systemd[1]: Starting Daily apt upgrade and clean activities... May 03 15:00:15 minidsp-shd volumio[956]: info: Loading plugin "manifestui"... May 03 15:00:16 minidsp-shd volumio[956]: info: Loading plugin "metavolumio"... May 03 15:00:16 minidsp-shd sudo[994]: pam_unix(sudo:session): session closed for user root May 03 15:00:16 minidsp-shd volumio-remote-updater[486]: [2024-05-03 15:00:16] [connect] Successful connection May 03 15:00:16 minidsp-shd systemd[1]: apt-daily-upgrade.service: Succeeded. May 03 15:00:16 minidsp-shd systemd[1]: Started Daily apt upgrade and clean activities. May 03 15:00:17 minidsp-shd volumio[956]: info: Loading plugin "airplay_emulation"... May 03 15:00:18 minidsp-shd volumio[956]: info: Starting Shairport Sync May 03 15:00:18 minidsp-shd volumio[956]: info: Loading plugin "cd_controller"... May 03 15:00:18 minidsp-shd volumio[956]: info: Loading plugin "last_100"... May 03 15:00:18 minidsp-shd volumio[956]: info: Plugin raat is not enabled May 03 15:00:18 minidsp-shd volumio[956]: info: Loading plugin "streaming_services"... May 03 15:00:19 minidsp-shd sudo[1002]: pam_unix(sudo:session): session closed for user root May 03 15:00:19 minidsp-shd sudo[1000]: pam_unix(sudo:session): session closed for user root May 03 15:00:20 minidsp-shd volumio[956]: info: Starting Streaming Service Transparent Proxy May 03 15:00:20 minidsp-shd volumio[956]: info: Plugin tidalconnect is not enabled May 03 15:00:20 minidsp-shd volumio[956]: info: Loading plugin "webradio"... May 03 15:00:20 minidsp-shd volumio[956]: info: Loading plugin "i2s_dacs"... May 03 15:00:20 minidsp-shd volumio[956]: info: I2S DAC not set, start Auto-detection May 03 15:00:20 minidsp-shd volumio[956]: info: Loading plugin "volumiodiscovery"... May 03 15:00:20 minidsp-shd volumio[956]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 03 15:00:20 minidsp-shd volumio[956]: *** WARNING *** Please fix your application to use the native API of Avahi! May 03 15:00:20 minidsp-shd volumio[956]: *** WARNING *** For more information see May 03 15:00:20 minidsp-shd volumio[956]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 03 15:00:20 minidsp-shd volumio[956]: *** WARNING *** Please fix your application to use the native API of Avahi! May 03 15:00:20 minidsp-shd node[956]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 03 15:00:20 minidsp-shd volumio[956]: *** WARNING *** For more information see May 03 15:00:20 minidsp-shd node[956]: *** WARNING *** Please fix your application to use the native API of Avahi! May 03 15:00:20 minidsp-shd node[956]: *** WARNING *** For more information see May 03 15:00:20 minidsp-shd node[956]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 03 15:00:20 minidsp-shd node[956]: *** WARNING *** Please fix your application to use the native API of Avahi! May 03 15:00:20 minidsp-shd node[956]: *** WARNING *** For more information see May 03 15:00:20 minidsp-shd volumio[956]: info: Applying required configuration parameters for plugin volumiodiscovery May 03 15:00:20 minidsp-shd volumio[956]: info: Discovery: Started advertising with name: miniDSP SHD May 03 15:00:20 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 03 15:00:20 minidsp-shd volumio[956]: info: Loading plugin "soundcloud"... May 03 15:00:21 minidsp-shd volumio[956]: info: Loading plugin "spop"... May 03 15:00:21 minidsp-shd systemd[1]: systemd-fsckd.service: Succeeded. May 03 15:00:22 minidsp-shd volumio[956]: STREAMING PROXY: Starting server on port 3245 May 03 15:00:22 minidsp-shd volumio[956]: Node JS runtime: 14 May 03 15:00:23 minidsp-shd volumio[956]: info: Plugin multiroom is not enabled May 03 15:00:23 minidsp-shd volumio[956]: info: Loading plugin "outputs"... May 03 15:00:23 minidsp-shd volumio[956]: info: Loading plugin "albumart"... May 03 15:00:23 minidsp-shd volumio[956]: info: Plugin ms_surface_dial is not enabled May 03 15:00:23 minidsp-shd volumio[956]: info: Plugin example_plugin is not enabled May 03 15:00:23 minidsp-shd volumio[956]: info: Loading plugin "hi_res_audio"... May 03 15:00:24 minidsp-shd volumio[956]: Forking 3 albumart workers May 03 15:00:25 minidsp-shd volumio[956]: Starting albumart workers May 03 15:00:25 minidsp-shd volumio[956]: Starting albumart workers May 03 15:00:25 minidsp-shd volumio[956]: Starting albumart workers May 03 15:00:25 minidsp-shd volumio[956]: info: Applying required configuration parameters for plugin hi_res_audio May 03 15:00:25 minidsp-shd volumio[956]: info: Loading plugin "inputs"... May 03 15:00:26 minidsp-shd volumio[956]: info: Loading plugin "qobuz"... May 03 15:00:28 minidsp-shd volumio[956]: info: Loading plugin "tidal"... May 03 15:00:31 minidsp-shd volumio[956]: info: Loading plugin "oem_helper"... May 03 15:00:31 minidsp-shd volumio-remote-updater[486]: [2024-05-03 15:00:31] [connect] Successful connection May 03 15:00:32 minidsp-shd volumio[956]: info: Applying required configuration parameters for plugin oem_helper May 03 15:00:32 minidsp-shd volumio[956]: info: Loading plugin "updater_comm"... May 03 15:00:32 minidsp-shd volumio[956]: info: Plugin mpdemulation is not enabled May 03 15:00:32 minidsp-shd volumio[956]: info: Loading plugin "rest_api"... May 03 15:00:32 minidsp-shd volumio[956]: info: Loading plugin "websocket"... May 03 15:00:32 minidsp-shd volumio[956]: info: Loading i18n strings for locale en May 03 15:00:32 minidsp-shd volumio[956]: Updating browse sources language May 03 15:00:32 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::initPlayerControls May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: Express server listening on port 3000 May 03 15:00:33 minidsp-shd volumio[956]: [Metrics] WebUI: 25s 150.49ms May 03 15:00:33 minidsp-shd volumio[956]: info: CoreStateMachine::resetVolumioState May 03 15:00:33 minidsp-shd volumio[956]: info: CoreStateMachine::getcurrentVolume May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioRetrievevolume May 03 15:00:33 minidsp-shd volumio[956]: info: CoreStateMachine::pushState May 03 15:00:33 minidsp-shd volumio[956]: info: CorePlayQueue::getTrack 0 May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioPushState May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 03 15:00:33 minidsp-shd sudo[1185]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 03 15:00:33 minidsp-shd sudo[1185]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:33 minidsp-shd sudo[1185]: pam_unix(sudo:session): session closed for user root May 03 15:00:33 minidsp-shd sudo[1188]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 03 15:00:33 minidsp-shd sudo[1188]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:33 minidsp-shd volumio[956]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' May 03 15:00:33 minidsp-shd volumio[956]: info: Completed loading Core Plugins May 03 15:00:33 minidsp-shd sudo[1188]: pam_unix(sudo:session): session closed for user root May 03 15:00:33 minidsp-shd volumio[956]: info: Preparing to generate the ALSA configuration file May 03 15:00:33 minidsp-shd volumio[956]: info: Cannot mount NAS QNAP_Multi at system boot, trial number 1 ,retrying in 5 seconds May 03 15:00:33 minidsp-shd volumio[956]: info: Cannot mount NAS QNAP_Music at system boot, trial number 1 ,retrying in 5 seconds May 03 15:00:33 minidsp-shd volumio-remote-updater[486]: [2024-05-03 15:00:33] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1714762831 101 May 03 15:00:33 minidsp-shd volumio[956]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 May 03 15:00:33 minidsp-shd volumio[956]: info: Asound.conf file unchanged, so no further update is needed May 03 15:00:33 minidsp-shd volumio[956]: info: Output device has changed, restarting MPD May 03 15:00:33 minidsp-shd sudo[1196]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 03 15:00:33 minidsp-shd sudo[1196]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:33 minidsp-shd sudo[1196]: pam_unix(sudo:session): session closed for user root May 03 15:00:33 minidsp-shd volumio[956]: info: Output device has changed, restarting Shairport Sync May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 03 15:00:33 minidsp-shd sudo[1199]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 03 15:00:33 minidsp-shd sudo[1199]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:33 minidsp-shd systemd[1]: Listening on mpd.socket. May 03 15:00:33 minidsp-shd systemd[1]: Starting Music Player Daemon... May 03 15:00:33 minidsp-shd volumio[956]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 03 15:00:33 minidsp-shd volumio[956]: info: ___________ START PLUGINS ___________ May 03 15:00:33 minidsp-shd volumio[956]: info: ControllerMpd::onStart: Initializing MPD May 03 15:00:33 minidsp-shd volumio[956]: info: Creating MPD Configuration file May 03 15:00:33 minidsp-shd sudo[1206]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 03 15:00:33 minidsp-shd sudo[1206]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 03 15:00:33 minidsp-shd sudo[1206]: pam_unix(sudo:session): session closed for user root May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 03 15:00:33 minidsp-shd volumio[956]: info: [1714762833956] CoreMusicLibrary::Adding element Media Servers May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 03 15:00:33 minidsp-shd sudo[1209]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 03 15:00:33 minidsp-shd sudo[1209]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:33 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 03 15:00:34 minidsp-shd volumio[956]: info: Adding Manifest REST API Endpoints May 03 15:00:34 minidsp-shd volumio[956]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui May 03 15:00:34 minidsp-shd volumio[956]: info: Adding METAVOLUMIO REST API Endpoints May 03 15:00:34 minidsp-shd volumio[956]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio May 03 15:00:34 minidsp-shd volumio[956]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio May 03 15:00:34 minidsp-shd systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM May 03 15:00:34 minidsp-shd systemd[1]: mpd.service: Succeeded. May 03 15:00:34 minidsp-shd volumio[956]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio May 03 15:00:34 minidsp-shd volumio[956]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio May 03 15:00:34 minidsp-shd systemd[1]: Stopped Music Player Daemon. May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 03 15:00:34 minidsp-shd sudo[1212]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name miniDSP SHD May 03 15:00:34 minidsp-shd sudo[1212]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:34 minidsp-shd systemd[1]: Starting Music Player Daemon... May 03 15:00:34 minidsp-shd kernel: Bluetooth: Core ver 2.22 May 03 15:00:34 minidsp-shd kernel: NET: Registered protocol family 31 May 03 15:00:34 minidsp-shd kernel: Bluetooth: HCI device and connection manager initialized May 03 15:00:34 minidsp-shd kernel: Bluetooth: HCI socket layer initialized May 03 15:00:34 minidsp-shd kernel: Bluetooth: L2CAP socket layer initialized May 03 15:00:34 minidsp-shd kernel: Bluetooth: SCO socket layer initialized May 03 15:00:34 minidsp-shd sudo[1212]: pam_unix(sudo:session): session closed for user root May 03 15:00:34 minidsp-shd volumio[956]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 03 15:00:34 minidsp-shd volumio[956]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 03 15:00:34 minidsp-shd volumio[956]: info: Preparing CD Folders May 03 15:00:34 minidsp-shd volumio[956]: info: Adding CD REST API Endpoints May 03 15:00:34 minidsp-shd volumio[956]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller May 03 15:00:34 minidsp-shd volumio[956]: info: Starting UDEV Watcher for CD May 03 15:00:34 minidsp-shd volumio[956]: info: Detecting CD presence with UDEV May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 03 15:00:34 minidsp-shd volumio[956]: info: [1714762834209] CoreMusicLibrary::Adding element Last_100 May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 03 15:00:34 minidsp-shd volumio[956]: info: Streaming services startup May 03 15:00:34 minidsp-shd volumio[956]: info: Starting Streaming Daemon May 03 15:00:34 minidsp-shd sudo[1225]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 03 15:00:34 minidsp-shd sudo[1225]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:34 minidsp-shd sudo[1225]: pam_unix(sudo:session): session closed for user root May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 03 15:00:34 minidsp-shd volumio[956]: info: [1714762834335] CoreMusicLibrary::Adding element Webradio May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 03 15:00:34 minidsp-shd volumio[956]: info: [1714762834367] CoreMusicLibrary::Adding element SoundCloud May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 03 15:00:34 minidsp-shd volumio[956]: Cannot find translation for source SoundCloud May 03 15:00:34 minidsp-shd volumio[956]: info: Creating Spotify config file May 03 15:00:34 minidsp-shd volumio[956]: error: Hi Res Audio Failed Login: Missing Login Data May 03 15:00:34 minidsp-shd volumio[956]: info: Adding HIGHRESAUDIO REST API Endpoints May 03 15:00:34 minidsp-shd volumio[956]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 03 15:00:34 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 03 15:00:34 minidsp-shd volumio[956]: info: Volumio Calling Home May 03 15:00:34 minidsp-shd volumio[956]: info: Stopping AccessToken refresher cron for QOBUZ May 03 15:00:34 minidsp-shd volumio[956]: info: AccessToken refresher cron started for QOBUZ May 03 15:00:34 minidsp-shd volumio[956]: info: Stopping AccessToken refresher cron May 03 15:00:34 minidsp-shd volumio[956]: info: AccessToken refresher cron started May 03 15:00:34 minidsp-shd volumio[956]: info: Adding TIDAL REST API Endpoints May 03 15:00:34 minidsp-shd volumio[956]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal May 03 15:00:34 minidsp-shd volumio[956]: info: Adding QOBUZ REST API Endpoints May 03 15:00:34 minidsp-shd volumio[956]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz May 03 15:00:35 minidsp-shd volumio[956]: info: Setting Device type: NanoPi NEO 2 May 03 15:00:35 minidsp-shd volumio[956]: info: CoreStateMachine::setRepeat undefined single undefined May 03 15:00:35 minidsp-shd volumio[956]: info: CoreStateMachine::pushState May 03 15:00:35 minidsp-shd volumio[956]: info: CorePlayQueue::getTrack 0 May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioPushState May 03 15:00:35 minidsp-shd volumio[956]: info: CoreStateMachine::setRandom undefined May 03 15:00:35 minidsp-shd volumio[956]: info: CoreStateMachine::pushState May 03 15:00:35 minidsp-shd volumio[956]: info: CorePlayQueue::getTrack 0 May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioPushState May 03 15:00:35 minidsp-shd volumio[956]: info: Serial port opened successfully May 03 15:00:35 minidsp-shd volumio[956]: error: Cannot start Volumio Streaming Daemon May 03 15:00:35 minidsp-shd volumio[956]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 03 15:00:35 minidsp-shd volumio[956]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 03 15:00:35 minidsp-shd volumio[956]: error: Cannot set new Bluetooth Name : Error: Command failed: /usr/bin/sudo /bin/hciconfig hci0 name 'miniDSP SHD' May 03 15:00:35 minidsp-shd volumio[956]: Can't get device info: No such device May 03 15:00:35 minidsp-shd volumio[956]: info: MPD Permissions set May 03 15:00:35 minidsp-shd volumio[956]: info: MPD Permissions set May 03 15:00:35 minidsp-shd volumio[956]: info: Volumio called home May 03 15:00:35 minidsp-shd volumio[956]: info: Spotify config file written May 03 15:00:35 minidsp-shd sudo[1247]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 03 15:00:35 minidsp-shd sudo[1247]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:35 minidsp-shd systemd[1]: Started UPnP Renderer front-end to MPD. May 03 15:00:35 minidsp-shd sudo[1250]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 03 15:00:35 minidsp-shd sudo[1247]: pam_unix(sudo:session): session closed for user root May 03 15:00:35 minidsp-shd sudo[1250]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:35 minidsp-shd volumio[956]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd systemd[1]: Started go-librespot Daemon. May 03 15:00:35 minidsp-shd sudo[1250]: pam_unix(sudo:session): session closed for user root May 03 15:00:35 minidsp-shd go-librespot[1253]: Librespot-go daemon starting... May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:35 minidsp-shd volumio[956]: info: Discovery: adding 66bace2a-2ddf-4180-ad4a-dd10c8db8260 May 03 15:00:35 minidsp-shd volumio[956]: info: Discovery: Found device miniDSP SHD May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioGetState May 03 15:00:35 minidsp-shd volumio[956]: info: CorePlayQueue::getTrack 0 May 03 15:00:35 minidsp-shd volumio[956]: info: Discovery: this is already registered, 66bace2a-2ddf-4180-ad4a-dd10c8db8260 May 03 15:00:35 minidsp-shd volumio[956]: info: Discovery: Found device miniDSP SHD May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioGetState May 03 15:00:35 minidsp-shd volumio[956]: info: CorePlayQueue::getTrack 0 May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: raat , reconfigureAndRestartRaat May 03 15:00:35 minidsp-shd volumio[956]: info: Adding MINIDSP Inputs May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 03 15:00:35 minidsp-shd volumio[956]: info: [1714762835520] CoreMusicLibrary::Adding element Inputs May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 03 15:00:35 minidsp-shd volumio[956]: Cannot find translation for source SoundCloud May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 03 15:00:35 minidsp-shd volumio[956]: info: [1714762835526] CoreMusicLibrary::Adding element Presets May 03 15:00:35 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 03 15:00:35 minidsp-shd volumio[956]: Cannot find translation for source SoundCloud May 03 15:00:35 minidsp-shd volumio[956]: Cannot find translation for source Presets May 03 15:00:35 minidsp-shd volumio[956]: info: Upmpdcli Daemon Started May 03 15:00:35 minidsp-shd volumio[956]: info: Starting Shairport Sync May 03 15:00:35 minidsp-shd volumio[956]: info: Starting Shairport Sync May 03 15:00:35 minidsp-shd sudo[1273]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 03 15:00:35 minidsp-shd sudo[1273]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:35 minidsp-shd volumio[956]: info: Starting Shairport Sync May 03 15:00:35 minidsp-shd sudo[1276]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 03 15:00:35 minidsp-shd sudo[1276]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:35 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 03 15:00:35 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. May 03 15:00:35 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 03 15:00:35 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 03 15:00:35 minidsp-shd sudo[1273]: pam_unix(sudo:session): session closed for user root May 03 15:00:35 minidsp-shd sudo[1279]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 03 15:00:35 minidsp-shd sudo[1279]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:35 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 03 15:00:35 minidsp-shd systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 03 15:00:35 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. May 03 15:00:35 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 03 15:00:35 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 03 15:00:35 minidsp-shd sudo[1276]: pam_unix(sudo:session): session closed for user root May 03 15:00:35 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 03 15:00:35 minidsp-shd systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 03 15:00:35 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. May 03 15:00:35 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 03 15:00:35 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 03 15:00:35 minidsp-shd sudo[1279]: pam_unix(sudo:session): session closed for user root May 03 15:00:35 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:35-04:00" level=info msg="generated new device id: e7a47779cd05c1653841a2f95c49f1a0e55d696c" May 03 15:00:35 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:35-04:00" level=debug msg="stored credentials found for 1228735792" May 03 15:00:36 minidsp-shd volumio[956]: info: Shairport-Sync Started May 03 15:00:36 minidsp-shd volumio[956]: Error adding Membership: Error: addMembership EINVAL May 03 15:00:36 minidsp-shd volumio[956]: info: Shairport-Sync Started May 03 15:00:36 minidsp-shd volumio[956]: info: Shairport-Sync Started May 03 15:00:36 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioGetState May 03 15:00:36 minidsp-shd volumio[956]: info: CorePlayQueue::getTrack 0 May 03 15:00:36 minidsp-shd volumio[956]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 03 15:00:36 minidsp-shd volumio[956]: SPOTIFY: BQAPsrxOesVKU42diNyn2EBcJtGPfNp13HW1DJ16p7WIP73gAff6L4H9-VagNPmuvS9zYAGFVumvBvvu-QVRzkvB-qwR2OZKG9HBZubSY2E9cz5zHAfF7hMdcB9zXebaS0eKAiGsJKHVpOAdJwnyrEO3G8PO56waWmX0Xiyxt4tnWzbblmlk9RrHM4NnD-DKzP8WiZdSOK7dVQ53MshPCnKi2woZONmBAQYF-MwHt-ixkDLoVSlnaYsiFN8KIw May 03 15:00:36 minidsp-shd volumio[956]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 03 15:00:36 minidsp-shd volumio[956]: info: New Spotify access token = BQAPsrxOesVKU42diNyn2EBcJtGPfNp13HW1DJ16p7WIP73gAff6L4H9-VagNPmuvS9zYAGFVumvBvvu-QVRzkvB-qwR2OZKG9HBZubSY2E9cz5zHAfF7hMdcB9zXebaS0eKAiGsJKHVpOAdJwnyrEO3G8PO56waWmX0Xiyxt4tnWzbblmlk9RrHM4NnD-DKzP8WiZdSOK7dVQ53MshPCnKi2woZONmBAQYF-MwHt-ixkDLoVSlnaYsiFN8KIw May 03 15:00:36 minidsp-shd volumio[956]: info: Spotify credentials grant success - running version from March 24, 2019 May 03 15:00:36 minidsp-shd volumio[956]: info: CorePlayQueue::getTrack 0 May 03 15:00:36 minidsp-shd volumio[956]: info: CoreCommandRouter::volumiosetSourceActiveno-source May 03 15:00:36 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 03 15:00:36 minidsp-shd volumio[956]: Cannot find translation for source SoundCloud May 03 15:00:36 minidsp-shd volumio[956]: Cannot find translation for source Presets May 03 15:00:36 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioStop May 03 15:00:36 minidsp-shd volumio[956]: info: CoreStateMachine::stop May 03 15:00:36 minidsp-shd volumio[956]: info: CoreStateMachine::setConsumeUpdateService undefined May 03 15:00:36 minidsp-shd volumio[956]: info: Notifying Active Input {"trackType":"input","service":"inputs","title":"SPDIF","disableUiControls":true,"albumart":"/albumart"} May 03 15:00:36 minidsp-shd volumio[956]: info: CoreStateMachine::setConsumeUpdateService undefined May 03 15:00:36 minidsp-shd volumio[956]: SPOTIFY: User informations: {"display_name":"1228735792","external_urls":{"spotify":"https://open.spotify.com/user/1228735792"},"href":"https://api.spotify.com/v1/users/1228735792","id":"1228735792","images":[],"type":"user","uri":"spotify:user:1228735792","followers":{"href":null,"total":5},"country":"US","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"bruce.frausto@gmail.com"} May 03 15:00:36 minidsp-shd volumio[956]: info: Spotify Successfully logged in May 03 15:00:36 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 03 15:00:36 minidsp-shd volumio[956]: info: [1714762836406] CoreMusicLibrary::Adding element Spotify May 03 15:00:36 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 03 15:00:36 minidsp-shd volumio[956]: Cannot find translation for source SoundCloud May 03 15:00:36 minidsp-shd volumio[956]: Cannot find translation for source Presets May 03 15:00:36 minidsp-shd volumio[956]: Cannot find translation for source Spotify May 03 15:00:36 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:36-04:00" level=debug msg="obtained new client token: AABA47kVudjSy/p3zt3zMhPHoa22gw1ZUWtbUBIUzKkPwKwAOBHfneMbeJDlWZz4qUAL94ByUudP+G6Ol5R7M+XlGOOrhs34cyG9DLdcVIx3ySTH7WRuyFqQ/y/jwah8N3qnURtUjgCtaSpaCvsGr54bHKW+u6FKgcBWViGGoEI4d8ynLO0crn7rO3pOMSBOovTFT71RjbLgngvu6MjfEUtBenR5A7Krd1r6XFgCTzZ0lmNzdzYQhKj82CfNwA==" May 03 15:00:36 minidsp-shd volumio[956]: info: CoreCommandRouter::servicePushState May 03 15:00:36 minidsp-shd volumio[956]: info: CoreStateMachine::pushState May 03 15:00:36 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 03 15:00:36 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioPushState May 03 15:00:36 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:36-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" May 03 15:00:36 minidsp-shd volumio[956]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 3 May 03 15:00:36 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:36-04:00" level=debug msg="completed keyexchange" May 03 15:00:37 minidsp-shd sudo[1288]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service May 03 15:00:37 minidsp-shd sudo[1288]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:37 minidsp-shd systemd[1]: Started Volumio Bluetooth Module. May 03 15:00:37 minidsp-shd sudo[1288]: pam_unix(sudo:session): session closed for user root May 03 15:00:37 minidsp-shd sudo[1291]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth/* May 03 15:00:37 minidsp-shd sudo[1291]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:37 minidsp-shd volumiobt[1290]: /bin/chmod: cannot access '/var/lib/bluetooth/*': No such file or directory May 03 15:00:37 minidsp-shd sudo[1291]: pam_unix(sudo:session): session closed for user root May 03 15:00:37 minidsp-shd volumio[956]: info: Volumio BT Module successfully started May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="completed challenge" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="authenticated as 1228735792" May 03 15:00:37 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 03 15:00:37 minidsp-shd volumio[956]: info: Enabling external Volume Control May 03 15:00:37 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:37 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="authenticated as 1228735792" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="dealer connection opened" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" May 03 15:00:37 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:37-04:00" level=debug msg="received connection id: MTZjYTAxMDAtMmI3NC00YjcxLTkwNGYtOTQ1YWVlMTlmY2FkK2RlYWxlcit0Y3A6Ly9ndWUxLWRlYWxlci1hLWg5dHIuZ3VlMS5zcG90aWZ5Lm5ldDo1NzAwKzgwREYxMjhDODM2ODBGOEYyRkI1NEYzMUY1RkY3MERBQ0E0OUJGQzVEOThFQkYxQzY0QzgzOTYwRjc1RDNCQUM=" May 03 15:00:38 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:38-04:00" level=debug msg="put connect state because NEW_DEVICE" May 03 15:00:38 minidsp-shd sudo[1294]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall pulseaudio May 03 15:00:38 minidsp-shd sudo[1294]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:38 minidsp-shd volumiobt[1290]: pulseaudio: no process found May 03 15:00:38 minidsp-shd sudo[1294]: pam_unix(sudo:session): session closed for user root May 03 15:00:38 minidsp-shd dbus-daemon[499]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.13' (uid=1000 pid=1298 comm="/usr/bin/pulseaudio --high-priority=true ") May 03 15:00:38 minidsp-shd systemd[1]: Starting RealtimeKit Scheduling Policy Service... May 03 15:00:38 minidsp-shd volumio[956]: ------------------------------------ BT MESSAGE: BT STATUS: running May 03 15:00:38 minidsp-shd dbus-daemon[499]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1' May 03 15:00:38 minidsp-shd systemd[1]: Started RealtimeKit Scheduling Policy Service. May 03 15:00:38 minidsp-shd rtkit-daemon[1299]: Successfully called chroot. May 03 15:00:38 minidsp-shd rtkit-daemon[1299]: Successfully dropped privileges. May 03 15:00:38 minidsp-shd rtkit-daemon[1299]: Successfully limited resources. May 03 15:00:38 minidsp-shd rtkit-daemon[1299]: Canary thread running. May 03 15:00:38 minidsp-shd rtkit-daemon[1299]: Running. May 03 15:00:38 minidsp-shd rtkit-daemon[1299]: Watchdog thread running. May 03 15:00:38 minidsp-shd dbus-daemon[499]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.14' (uid=0 pid=1299 comm="/usr/lib/rtkit/rtkit-daemon ") May 03 15:00:38 minidsp-shd systemd[1]: Starting Authorization Manager... May 03 15:00:38 minidsp-shd volumio[956]: ------------------------------------ BT MESSAGE: BT STATUS: running May 03 15:00:38 minidsp-shd mpd[1213]: May 03 15:00 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 03 15:00:38 minidsp-shd polkitd[1302]: started daemon version 0.105 using authority implementation `local' version `0.105' May 03 15:00:38 minidsp-shd dbus-daemon[499]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' May 03 15:00:38 minidsp-shd systemd[1]: Started Authorization Manager. May 03 15:00:38 minidsp-shd sudo[1307]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=bruce,password=carlos338!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.20/Multimedia /mnt/NAS/QNAP_Multi May 03 15:00:38 minidsp-shd sudo[1307]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:38 minidsp-shd systemd[1]: Started Music Player Daemon. May 03 15:00:38 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 03 15:00:38 minidsp-shd sudo[1199]: pam_unix(sudo:session): session closed for user root May 03 15:00:38 minidsp-shd volumio[956]: Upnp client error: Error: This socket has been ended by the other party May 03 15:00:38 minidsp-shd sudo[1209]: pam_unix(sudo:session): session closed for user root May 03 15:00:38 minidsp-shd sudo[1310]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=bruce,password=carlos338!,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.20/Music /mnt/NAS/QNAP_Music May 03 15:00:38 minidsp-shd sudo[1310]: pam_unix(sudo:session): session opened for user root by (uid=0) May 03 15:00:38 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 03 15:00:38 minidsp-shd volumio[956]: info: Completed starting Core Plugins May 03 15:00:38 minidsp-shd volumio[956]: info: ------------------------------------------- May 03 15:00:38 minidsp-shd volumio[956]: info: ----- MyVolumio plugins startup ---- May 03 15:00:38 minidsp-shd volumio[956]: info: ------------------------------------------- May 03 15:00:38 minidsp-shd volumio[956]: info: [MyVolumio PluginManager] Fetching plans data.... May 03 15:00:38 minidsp-shd volumio[956]: info: go-librespot daemon successfully initialized May 03 15:00:38 minidsp-shd volumio[956]: info: CoreStateMachine::pushState May 03 15:00:38 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 03 15:00:38 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioPushState May 03 15:00:38 minidsp-shd volumio[956]: info: MPD running with PID1213 May 03 15:00:38 minidsp-shd volumio[956]: ,establishing connection May 03 15:00:38 minidsp-shd volumio[956]: error: MPD error: The expression evaluated to a falsy value: May 03 15:00:38 minidsp-shd volumio[956]: assert.ok(self.idling) May 03 15:00:38 minidsp-shd volumio[956]: error: The expression evaluated to a falsy value: May 03 15:00:38 minidsp-shd volumio[956]: assert.ok(self.idling) May 03 15:00:38 minidsp-shd volumio[956]: error: MPD error: The expression evaluated to a falsy value: May 03 15:00:38 minidsp-shd volumio[956]: assert.ok(self.idling) May 03 15:00:38 minidsp-shd volumio[956]: error: The expression evaluated to a falsy value: May 03 15:00:38 minidsp-shd volumio[956]: assert.ok(self.idling) May 03 15:00:38 minidsp-shd volumio[956]: error: updateQueue error: null May 03 15:00:38 minidsp-shd dbus-daemon[499]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.34' (uid=1000 pid=1298 comm="/usr/bin/pulseaudio --high-priority=true ") May 03 15:00:38 minidsp-shd systemd[1]: Starting Bluetooth service... May 03 15:00:39 minidsp-shd volumio[956]: ------------------------------------ BT MESSAGE: BT STATUS: running May 03 15:00:39 minidsp-shd bluetoothd[1321]: Bluetooth daemon 5.23 May 03 15:00:39 minidsp-shd dbus-daemon[499]: [system] Successfully activated service 'org.bluez' May 03 15:00:39 minidsp-shd systemd[1]: Started Bluetooth service. May 03 15:00:39 minidsp-shd bluetoothd[1321]: Starting SDP server May 03 15:00:39 minidsp-shd kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 May 03 15:00:39 minidsp-shd kernel: Bluetooth: BNEP filters: protocol multicast May 03 15:00:39 minidsp-shd kernel: Bluetooth: BNEP socket layer initialized May 03 15:00:39 minidsp-shd pulseaudio[1298]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 May 03 15:00:39 minidsp-shd pulseaudio[1298]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 May 03 15:00:39 minidsp-shd volumiobt[1290]: Applying permissions May 03 15:00:39 minidsp-shd volumiobt[1290]: Setting BT discoverable and pairable May 03 15:00:39 minidsp-shd dbus-daemon[499]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.35' (uid=0 pid=1321 comm="/usr/local/libexec/bluetooth/bluetoothd ") May 03 15:00:39 minidsp-shd bluetoothd[1321]: Bluetooth management interface 1.14 initialized May 03 15:00:39 minidsp-shd pulseaudio[1298]: 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 03 15:00:39 minidsp-shd systemd[1]: Starting Hostname Service... May 03 15:00:39 minidsp-shd volumiobt[1290]: [38B blob data] May 03 15:00:39 minidsp-shd volumiobt[1290]: Invalid command May 03 15:00:39 minidsp-shd volumiobt[1290]: [bluetooth]# agent on May 03 15:00:39 minidsp-shd volumiobt[1290]: [bluetooth]# discoverable on May 03 15:00:39 minidsp-shd volumiobt[1290]: No default controller available May 03 15:00:39 minidsp-shd volumiobt[1290]: [bluetooth]# pairable on May 03 15:00:39 minidsp-shd volumiobt[1290]: No default controller available May 03 15:00:39 minidsp-shd volumiobt[1290]: [bluetooth]# agent NoInputNoOutput May 03 15:00:39 minidsp-shd volumiobt[1290]: Failed to register agent object May 03 15:00:39 minidsp-shd volumiobt[1290]: [bluetooth]# default-agent May 03 15:00:39 minidsp-shd volumiobt[1290]: No agent is registered May 03 15:00:39 minidsp-shd volumiobt[1290]: [bluetooth]# quit May 03 15:00:39 minidsp-shd volumiobt[1290]: [61B blob data] May 03 15:00:39 minidsp-shd volumio[956]: ------------------------------------ BT MESSAGE: BT STATUS: running May 03 15:00:39 minidsp-shd volumiobt[1290]: [62B blob data] May 03 15:00:39 minidsp-shd dbus-daemon[499]: [system] Successfully activated service 'org.freedesktop.hostname1' May 03 15:00:39 minidsp-shd systemd[1]: Started Hostname Service. May 03 15:00:39 minidsp-shd volumio[1251]: Generating RSA private key, 4096 bit long modulus (2 primes) May 03 15:00:39 minidsp-shd volumio[956]: info: CoreStateMachine::pushState May 03 15:00:39 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 03 15:00:39 minidsp-shd volumio[956]: info: CoreCommandRouter::volumioPushState May 03 15:00:39 minidsp-shd volumio[956]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume May 03 15:00:39 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:39-04:00" level=debug msg="handling transfer player command from 94c35828d2a44d90e4beae9ea9fccd16faf59b93" May 03 15:00:39 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:39-04:00" level=debug msg="loading track spotify:track:6rAfSP35TDiQeYuFGJaXRv (paused: true, position: 33044ms)" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=trace msg="emitting websocket event: will_play" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1331" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6rAfSP35TDiQeYuFGJaXRv" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="requested aes key for file 42e95aa0cc4b452e4c56e85ff9439d641226a912, gid: 6rAfSP35TDiQeYuFGJaXRv" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="fetched first chunk of 15, total size is 7807204 bytes" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="fetched chunk 1/14, size: 524288" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="fetched chunk 2/14, size: 524288" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=trace msg="seek to 33044ms (diff: 111ms, samples: 1457240, bytes: 1482215)" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=info msg="loaded track \"Oooh Love\" (uri: spotify:track:6rAfSP35TDiQeYuFGJaXRv, paused: true, position: 33044ms, duration: 169090ms)" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="fetched chunk 4/14, size: 524288" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="fetched chunk 3/14, size: 524288" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="fetched chunk 5/14, size: 524288" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=trace msg="emitting websocket event: metadata" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=trace msg="emitting websocket event: active" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="sending successful reply for delaer request" May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 03 15:00:40 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:40-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 03 15:00:41 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:41-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 03 15:00:41 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:41-04:00" level=trace msg="emitting websocket event: paused" May 03 15:00:41 minidsp-shd volumio[956]: info: Initializing connection to go-librespot Websocket May 03 15:00:41 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:41-04:00" level=debug msg="new websocket client" May 03 15:00:41 minidsp-shd volumio[956]: info: Connection to go-librespot Websocket established May 03 15:00:43 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:43-04:00" level=debug msg="handling resume player command from 94c35828d2a44d90e4beae9ea9fccd16faf59b93" May 03 15:00:43 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:43-04:00" level=trace msg="seek to 33044ms (diff: 111ms, samples: 1457240, bytes: 1482215)" May 03 15:00:43 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:43-04:00" level=debug msg="resume track at 32562ms" May 03 15:00:43 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:43-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 03 15:00:43 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:43-04:00" level=debug msg="sending successful reply for delaer request" May 03 15:00:43 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:43-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 03 15:00:43 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:43-04:00" level=trace msg="emitting websocket event: playing" May 03 15:00:43 minidsp-shd volumio[956]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6rAfSP35TDiQeYuFGJaXRv","play_origin":"album"}} May 03 15:00:43 minidsp-shd volumio[956]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 03 15:00:43 minidsp-shd volumio[956]: TypeError: Cannot read property 'service' of undefined May 03 15:00:43 minidsp-shd volumio[956]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:322:50) May 03 15:00:43 minidsp-shd volumio[956]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:248:18) May 03 15:00:43 minidsp-shd volumio[956]: at WebSocket.message (/data/plugins/music_service/spop/index.js:175:14) May 03 15:00:43 minidsp-shd volumio[956]: at WebSocket.emit (events.js:400:28) May 03 15:00:43 minidsp-shd volumio[956]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1192:20) May 03 15:00:43 minidsp-shd volumio[956]: at Receiver.emit (events.js:400:28) May 03 15:00:43 minidsp-shd volumio[956]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:560:14) May 03 15:00:43 minidsp-shd volumio[956]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:478:17) May 03 15:00:43 minidsp-shd volumio[956]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:22) May 03 15:00:43 minidsp-shd volumio[956]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:180:18 May 03 15:00:43 minidsp-shd volumio[956]: at internal/process/task_queues.js:141:7 May 03 15:00:43 minidsp-shd volumio[956]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) May 03 15:00:43 minidsp-shd volumio[956]: at AsyncResource.runMicrotask (internal/process/task_queues.js:138:8) May 03 15:00:43 minidsp-shd volumio[956]: at processTicksAndRejections (internal/process/task_queues.js:95:5) May 03 15:00:43 minidsp-shd volumio[956]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 03 15:00:43 minidsp-shd go-librespot[1253]: time="2024-05-03T15:00:43-04:00" level=debug msg="fetched chunk 6/14, size: 524288" May 03 15:00:44 minidsp-shd volumio[1251]: ................................................++++ May 03 15:00:44 minidsp-shd sudo[1353]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-03 14:59 May 03 15:00:44 minidsp-shd sudo[1353]: 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:00:28 PM CET" VOLUMIO_VERSION="3.608" VOLUMIO_HARDWARE="nanopineo2" VOLUMIO_DEVICENAME="NanoPi Neo2" VOLUMIO_VENDOR="miniDSP" VOLUMIO_MODEL="SHD" VOLUMIO_VENDOR_MODEL="miniDSP SHD" VOLUMIO_HASH="29ccfe8a9cff19911db4b736879ac117"