-- Logs begin at Tue 2024-03-26 03:37:45 +08, end at Sat 2024-11-02 14:55:04 +08. -- Nov 02 14:54:30 minidsp-shd ntpd[815]: receive: Unexpected origin timestamp 0xe9ac5126.daeddc06 does not match aorg 0000000000.00000000 from server@144.126.242.176 xmt 0xead04b26.31b6e35a Nov 02 14:54:30 minidsp-shd ntpd[815]: receive: Unexpected origin timestamp 0xe9ac5126.daf39485 does not match aorg 0000000000.00000000 from server@172.104.34.44 xmt 0xead04b26.33b88a4c Nov 02 14:54:30 minidsp-shd ntpd[815]: receive: Unexpected origin timestamp 0xe9ac5126.daf09ced does not match aorg 0000000000.00000000 from server@159.223.60.208 xmt 0xead04b26.31f1e65c Nov 02 14:54:30 minidsp-shd ntpd[815]: receive: Unexpected origin timestamp 0xe9ac5126.dac94419 does not match aorg 0000000000.00000000 from server@47.241.41.246 xmt 0xead04b26.31773ab1 Nov 02 14:54:30 minidsp-shd ntpd[815]: receive: Unexpected origin timestamp 0xe9ac5126.daead5ef does not match aorg 0000000000.00000000 from server@129.150.48.1 xmt 0xead04b26.31cd420a Nov 02 14:54:30 minidsp-shd ntpd[815]: receive: Unexpected origin timestamp 0xe9ac5126.daf65dd9 does not match aorg 0000000000.00000000 from server@162.159.200.1 xmt 0xead04b26.31b81cd8 Nov 02 14:54:30 minidsp-shd systemd[1]: Starting Daily apt download activities... Nov 02 14:54:31 minidsp-shd systemd[1]: apt-daily.service: Succeeded. Nov 02 14:54:31 minidsp-shd systemd[1]: Started Daily apt download activities. Nov 02 14:54:31 minidsp-shd systemd[1]: Starting Daily apt upgrade and clean activities... Nov 02 14:54:31 minidsp-shd volumio[639]: info: Loading plugin "airplay_emulation"... Nov 02 14:54:31 minidsp-shd volumio[639]: info: Starting Shairport Sync Nov 02 14:54:31 minidsp-shd volumio[639]: info: Loading plugin "cd_controller"... Nov 02 14:54:32 minidsp-shd volumio-remote-updater[456]: [2024-11-02 14:54:32] [connect] Successful connection Nov 02 14:54:32 minidsp-shd volumio[639]: info: Loading plugin "last_100"... Nov 02 14:54:32 minidsp-shd volumio[639]: info: Loading plugin "raat"... Nov 02 14:54:32 minidsp-shd systemd[1]: systemd-fsckd.service: Succeeded. Nov 02 14:54:32 minidsp-shd systemd[1]: apt-daily-upgrade.service: Succeeded. Nov 02 14:54:32 minidsp-shd systemd[1]: Started Daily apt upgrade and clean activities. Nov 02 14:54:32 minidsp-shd volumio[639]: info: RAAT Plugin loaded Nov 02 14:54:33 minidsp-shd volumio[639]: info: Adding restartRAATSocket REST API Endpoint Nov 02 14:54:33 minidsp-shd volumio[639]: info: Adding restartRAATSocket REST Endpoint for plugin: music_service/raat Nov 02 14:54:33 minidsp-shd volumio[639]: info: Loading plugin "streaming_services"... Nov 02 14:54:35 minidsp-shd volumio[639]: info: Starting Streaming Service Transparent Proxy Nov 02 14:54:35 minidsp-shd volumio[639]: info: Loading plugin "tidalconnect"... Nov 02 14:54:35 minidsp-shd volumio[639]: info: Loading plugin "webradio"... Nov 02 14:54:36 minidsp-shd volumio[639]: info: Loading plugin "i2s_dacs"... Nov 02 14:54:36 minidsp-shd volumio[639]: info: I2S DAC not set, start Auto-detection Nov 02 14:54:36 minidsp-shd volumio[639]: info: Loading plugin "volumiodiscovery"... Nov 02 14:54:36 minidsp-shd volumio[639]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 02 14:54:36 minidsp-shd node[639]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 02 14:54:36 minidsp-shd node[639]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 02 14:54:36 minidsp-shd volumio[639]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 02 14:54:36 minidsp-shd volumio[639]: *** WARNING *** For more information see Nov 02 14:54:36 minidsp-shd volumio[639]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 02 14:54:36 minidsp-shd volumio[639]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 02 14:54:36 minidsp-shd volumio[639]: *** WARNING *** For more information see Nov 02 14:54:36 minidsp-shd node[639]: *** WARNING *** For more information see Nov 02 14:54:36 minidsp-shd node[639]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 02 14:54:36 minidsp-shd node[639]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 02 14:54:36 minidsp-shd node[639]: *** WARNING *** For more information see Nov 02 14:54:36 minidsp-shd volumio[639]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 02 14:54:36 minidsp-shd volumio[639]: info: Discovery: Started advertising with name: miniDSP SHD Nov 02 14:54:36 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 02 14:54:36 minidsp-shd volumio[639]: info: Loading plugin "spop"... Nov 02 14:54:37 minidsp-shd volumio[639]: STREAMING PROXY: Starting server on port 3245 Nov 02 14:54:37 minidsp-shd volumio[639]: Node JS runtime: 14 Nov 02 14:54:39 minidsp-shd volumio[639]: info: Plugin multiroom is not enabled Nov 02 14:54:39 minidsp-shd volumio[639]: info: Loading plugin "outputs"... Nov 02 14:54:39 minidsp-shd volumio[639]: info: Loading plugin "albumart"... Nov 02 14:54:39 minidsp-shd volumio[639]: info: Plugin ms_surface_dial is not enabled Nov 02 14:54:39 minidsp-shd volumio[639]: info: Plugin example_plugin is not enabled Nov 02 14:54:39 minidsp-shd volumio[639]: info: Loading plugin "hi_res_audio"... Nov 02 14:54:40 minidsp-shd volumio[639]: Forking 3 albumart workers Nov 02 14:54:42 minidsp-shd volumio[639]: Starting albumart workers Nov 02 14:54:42 minidsp-shd volumio[639]: Starting albumart workers Nov 02 14:54:42 minidsp-shd volumio[639]: Starting albumart workers Nov 02 14:54:42 minidsp-shd volumio[639]: info: Applying required configuration parameters for plugin hi_res_audio Nov 02 14:54:42 minidsp-shd volumio[639]: info: Loading plugin "inputs"... Nov 02 14:54:44 minidsp-shd volumio[639]: info: Loading plugin "qobuz"... Nov 02 14:54:46 minidsp-shd volumio[639]: info: Loading plugin "tidal"... Nov 02 14:54:47 minidsp-shd volumio-remote-updater[456]: [2024-11-02 14:54:47] [connect] Successful connection Nov 02 14:54:49 minidsp-shd volumio[639]: info: Loading plugin "oem_helper"... Nov 02 14:54:51 minidsp-shd volumio[639]: info: Applying required configuration parameters for plugin oem_helper Nov 02 14:54:51 minidsp-shd volumio[639]: info: Loading plugin "updater_comm"... Nov 02 14:54:51 minidsp-shd volumio[639]: info: Plugin mpdemulation is not enabled Nov 02 14:54:51 minidsp-shd volumio[639]: info: Loading plugin "rest_api"... Nov 02 14:54:51 minidsp-shd volumio[639]: info: Loading plugin "websocket"... Nov 02 14:54:51 minidsp-shd volumio[639]: info: Loading i18n strings for locale en Nov 02 14:54:51 minidsp-shd volumio[639]: Updating browse sources language Nov 02 14:54:51 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::initPlayerControls Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 14:54:52 minidsp-shd volumio[639]: Express server listening on port 3000 Nov 02 14:54:52 minidsp-shd volumio[639]: [Metrics] WebUI: 41s 886.26ms Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreStateMachine::resetVolumioState Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreStateMachine::getcurrentVolume Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioRetrievevolume Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreStateMachine::pushState Nov 02 14:54:52 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioPushState Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 14:54:52 minidsp-shd sudo[1030]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 02 14:54:52 minidsp-shd sudo[1030]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: inputs , getVolume Nov 02 14:54:52 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: inputs , getDSP Nov 02 14:54:52 minidsp-shd sudo[1030]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:52 minidsp-shd sudo[1032]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 02 14:54:52 minidsp-shd sudo[1032]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:52 minidsp-shd volumio[639]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Nov 02 14:54:52 minidsp-shd volumio[639]: info: Completed loading Core Plugins Nov 02 14:54:52 minidsp-shd volumio[639]: info: Preparing to generate the ALSA configuration file Nov 02 14:54:52 minidsp-shd sudo[1032]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:52 minidsp-shd volumio[639]: info: Cannot mount NAS USB at system boot, trial number 1 ,retrying in 5 seconds Nov 02 14:54:52 minidsp-shd volumio[639]: info: Cannot mount NAS USB at system boot, trial number 1 ,retrying in 5 seconds Nov 02 14:54:52 minidsp-shd volumio[639]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Nov 02 14:54:52 minidsp-shd volumio[639]: wlan0 Interface doesn't support scanning. Nov 02 14:54:52 minidsp-shd volumio[639]: info: Cannot use regular scanning, forcing with ap-force Nov 02 14:54:52 minidsp-shd sudo[1038]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Nov 02 14:54:52 minidsp-shd sudo[1038]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:52 minidsp-shd sudo[1038]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:52 minidsp-shd volumio[639]: command failed: No such device (-19) Nov 02 14:54:52 minidsp-shd volumio[639]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Nov 02 14:54:52 minidsp-shd volumio[639]: command failed: No such device (-19) Nov 02 14:54:52 minidsp-shd volumio[639]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision Nov 02 14:54:53 minidsp-shd volumio[639]: info: Reloading queue from file Nov 02 14:54:53 minidsp-shd volumio[639]: info: Asound.conf file unchanged, so no further update is needed Nov 02 14:54:53 minidsp-shd volumio[639]: info: Output device has changed, restarting MPD Nov 02 14:54:53 minidsp-shd sudo[1048]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 02 14:54:53 minidsp-shd sudo[1048]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:53 minidsp-shd volumio[639]: info: Output device has changed, restarting Shairport Sync Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 14:54:53 minidsp-shd sudo[1048]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:53 minidsp-shd sudo[1050]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 02 14:54:53 minidsp-shd sudo[1050]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:53 minidsp-shd systemd[1]: Listening on mpd.socket. Nov 02 14:54:53 minidsp-shd systemd[1]: Starting Music Player Daemon... Nov 02 14:54:53 minidsp-shd volumio[639]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 02 14:54:53 minidsp-shd volumio[639]: info: ___________ START PLUGINS ___________ Nov 02 14:54:53 minidsp-shd volumio[639]: info: ControllerMpd::onStart: Initializing MPD Nov 02 14:54:53 minidsp-shd volumio[639]: info: Creating MPD Configuration file Nov 02 14:54:53 minidsp-shd sudo[1058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 02 14:54:53 minidsp-shd volumio[639]: info: [1730530493377] CoreMusicLibrary::Adding element Media Servers Nov 02 14:54:53 minidsp-shd sudo[1058]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 02 14:54:53 minidsp-shd sudo[1058]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:53 minidsp-shd sudo[1060]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 02 14:54:53 minidsp-shd sudo[1060]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 02 14:54:53 minidsp-shd systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Nov 02 14:54:53 minidsp-shd systemd[1]: mpd.service: Succeeded. Nov 02 14:54:53 minidsp-shd systemd[1]: Stopped Music Player Daemon. Nov 02 14:54:53 minidsp-shd systemd[1]: Starting Music Player Daemon... Nov 02 14:54:53 minidsp-shd volumio[639]: info: Adding Manifest REST API Endpoints Nov 02 14:54:53 minidsp-shd volumio[639]: info: Adding manifestui REST Endpoint for plugin: miscellanea/manifestui Nov 02 14:54:53 minidsp-shd volumio[639]: info: Adding METAVOLUMIO REST API Endpoints Nov 02 14:54:53 minidsp-shd volumio[639]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Nov 02 14:54:53 minidsp-shd volumio[639]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Nov 02 14:54:53 minidsp-shd volumio[639]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Nov 02 14:54:53 minidsp-shd volumio[639]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 14:54:53 minidsp-shd sudo[1065]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/hciconfig hci0 name miniDSP SHD Nov 02 14:54:53 minidsp-shd sudo[1065]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:53 minidsp-shd sudo[1065]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:53 minidsp-shd volumio[639]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 14:54:53 minidsp-shd volumio[639]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 02 14:54:53 minidsp-shd volumio[639]: info: Preparing CD Folders Nov 02 14:54:53 minidsp-shd volumio[639]: info: Adding CD REST API Endpoints Nov 02 14:54:53 minidsp-shd volumio[639]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Nov 02 14:54:53 minidsp-shd volumio[639]: info: Starting UDEV Watcher for CD Nov 02 14:54:53 minidsp-shd volumio[639]: info: Detecting CD presence with UDEV Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 02 14:54:53 minidsp-shd volumio[639]: info: [1730530493774] CoreMusicLibrary::Adding element Last_100 Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 02 14:54:53 minidsp-shd volumio[639]: info: Starting RAAT Plugin Nov 02 14:54:53 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Nov 02 14:54:53 minidsp-shd volumio[639]: info: Additional UI Settings Added for plugin music_service/raat Nov 02 14:54:53 minidsp-shd volumio[639]: info: Streaming services startup Nov 02 14:54:53 minidsp-shd volumio[639]: info: Starting Streaming Daemon Nov 02 14:54:53 minidsp-shd sudo[1076]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 02 14:54:53 minidsp-shd sudo[1076]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:53 minidsp-shd sudo[1076]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:54 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 02 14:54:54 minidsp-shd volumio[639]: info: [1730530494048] CoreMusicLibrary::Adding element Webradio Nov 02 14:54:54 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 02 14:54:54 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 02 14:54:54 minidsp-shd sudo[1083]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Nov 02 14:54:54 minidsp-shd sudo[1083]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:54 minidsp-shd volumio[639]: info: Creating Spotify config file Nov 02 14:54:54 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:54 minidsp-shd sudo[1083]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:54 minidsp-shd volumio[639]: info: Adding HIGHRESAUDIO REST API Endpoints Nov 02 14:54:54 minidsp-shd volumio[639]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Nov 02 14:54:54 minidsp-shd volumio[639]: info: Refreshing TIDAL token Nov 02 14:54:54 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 02 14:54:54 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 14:54:54 minidsp-shd volumio[639]: info: Volumio Calling Home Nov 02 14:54:54 minidsp-shd volumio[639]: info: Stopping AccessToken refresher cron for QOBUZ Nov 02 14:54:54 minidsp-shd volumio[639]: info: AccessToken refresher cron started for QOBUZ Nov 02 14:54:54 minidsp-shd volumio[639]: info: Adding QOBUZ REST API Endpoints Nov 02 14:54:54 minidsp-shd volumio[639]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreStateMachine::setRepeat false single undefined Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreStateMachine::pushState Nov 02 14:54:55 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioPushState Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreStateMachine::setRandom false Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreStateMachine::pushState Nov 02 14:54:55 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioPushState Nov 02 14:54:55 minidsp-shd volumio[639]: info: Setting Device type: NanoPi NEO 3 Nov 02 14:54:55 minidsp-shd volumio[639]: info: Serial port opened successfully Nov 02 14:54:55 minidsp-shd volumio[639]: error: Cannot start Volumio Streaming Daemon Nov 02 14:54:55 minidsp-shd volumio[639]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 02 14:54:55 minidsp-shd volumio[639]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 02 14:54:55 minidsp-shd volumio[639]: info: RAAT Albumart path created successfully Nov 02 14:54:55 minidsp-shd volumio[639]: error: Cannot set new Bluetooth Name : Error: Command failed: /usr/bin/sudo /bin/hciconfig hci0 name 'miniDSP SHD' Nov 02 14:54:55 minidsp-shd volumio[639]: Can't get device info: No such device Nov 02 14:54:55 minidsp-shd volumio[639]: info: MPD Permissions set Nov 02 14:54:55 minidsp-shd volumio[639]: info: MPD Permissions set Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreStateMachine::pushState Nov 02 14:54:55 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioPushState Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume Nov 02 14:54:55 minidsp-shd volumio[639]: info: Ignoring ROON Volume update because of undefined data Nov 02 14:54:55 minidsp-shd volumio[639]: info: Volumio called home Nov 02 14:54:55 minidsp-shd volumio[639]: info: Spotify config file written Nov 02 14:54:55 minidsp-shd sudo[1100]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 02 14:54:55 minidsp-shd sudo[1100]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP Nov 02 14:54:55 minidsp-shd volumio[639]: info: updateDSP function in raat called! Nov 02 14:54:55 minidsp-shd systemd[1]: Started UPnP Renderer front-end to MPD. Nov 02 14:54:55 minidsp-shd volumio[639]: info: Updating RAAT Signal Path Nov 02 14:54:55 minidsp-shd sudo[1100]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:55 minidsp-shd sudo[1103]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 02 14:54:55 minidsp-shd sudo[1103]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:55 minidsp-shd volumio[639]: error: Cannot write to RAAT Client: TypeError: Cannot read property 'write' of undefined Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: raat , reconfigureAndRestartRaat Nov 02 14:54:55 minidsp-shd volumio[639]: info: Reconfiguring and Restarting RAAT Plugin Nov 02 14:54:55 minidsp-shd systemd[1]: Started go-librespot Daemon. Nov 02 14:54:55 minidsp-shd sudo[1103]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:55 minidsp-shd go-librespot[1107]: Librespot-go daemon starting... Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: Not Reporting Auto name since its the default one Nov 02 14:54:55 minidsp-shd volumio[639]: info: RAAT Overriding default device vendor model Nov 02 14:54:55 minidsp-shd volumio[639]: info: Adding MINIDSP Inputs Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 02 14:54:55 minidsp-shd volumio[639]: info: [1730530495579] CoreMusicLibrary::Adding element Inputs Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 02 14:54:55 minidsp-shd volumio[639]: info: [1730530495587] CoreMusicLibrary::Adding element Presets Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 02 14:54:55 minidsp-shd volumio[639]: Cannot find translation for source Presets Nov 02 14:54:55 minidsp-shd volumio[639]: (node:639) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead. Nov 02 14:54:55 minidsp-shd volumio[639]: (Use `node --trace-deprecation ...` to show where the warning was created) Nov 02 14:54:55 minidsp-shd volumio[639]: info: Discovery: adding 07455d30-8467-47f0-a050-ef35e285f791 Nov 02 14:54:55 minidsp-shd volumio[639]: info: Discovery: Found device miniDSP SHD Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioGetState Nov 02 14:54:55 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:54:55 minidsp-shd volumio[639]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 1 Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Nov 02 14:54:55 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:55+08:00" level=info msg="generated new device id: f4c1fad58cb571391a6c98dda0cb5bb33f23dc49" Nov 02 14:54:55 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:55+08:00" level=debug msg="stored credentials found for 21mduk4js3hup4d45e2mxuhxy" Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 14:54:55 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Nov 02 14:54:56 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:56 minidsp-shd volumio[639]: info: Upmpdcli Daemon Started Nov 02 14:54:56 minidsp-shd volumio[639]: info: Starting Shairport Sync Nov 02 14:54:56 minidsp-shd volumio[639]: info: Starting Shairport Sync Nov 02 14:54:56 minidsp-shd volumio[639]: info: Starting Shairport Sync Nov 02 14:54:56 minidsp-shd sudo[1131]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 02 14:54:56 minidsp-shd sudo[1131]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:56 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Nov 02 14:54:56 minidsp-shd sudo[1134]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 02 14:54:56 minidsp-shd sudo[1134]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:56 minidsp-shd sudo[1137]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 02 14:54:56 minidsp-shd sudo[1137]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:56 minidsp-shd systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 02 14:54:56 minidsp-shd systemd[1]: shairport-sync.service: Succeeded. Nov 02 14:54:56 minidsp-shd systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 02 14:54:56 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:56+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 02 14:54:56 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:56+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 02 14:54:56 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:56+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 02 14:54:56 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:56+08:00" level=debug msg="zeroconf server listening on port 40893" Nov 02 14:54:56 minidsp-shd systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 02 14:54:56 minidsp-shd sudo[1137]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:56 minidsp-shd sudo[1131]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:56 minidsp-shd sudo[1134]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:56 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:56+08:00" level=debug msg="obtained new client token: AABELxofKAlbM8WapJLGdHj+BNTM8eiOBrZzOJ8o1w2XSO5R5v3B+o6zU3zmANHIOTjqBGSVLWxxeFbgD9jFg8Y/7/GAoegXjJltA9WsLEvy2zjNl0ukG0VxnHZ9nrVok8aBJGnj8sG4o08vnuhmFJi5cQBkQ1lCiP+4Q6PHkeA07E6hs7bKkyGak8mmqGxGKHHwwLYVC5KDQq6mAdMDfVUBjkLmjZV0uVNV/YOAuRdQL17eVKDP+tg4uZ8=" Nov 02 14:54:56 minidsp-shd volumio[639]: info: CoreCommandRouter::volumiosetSourceActiveno-source Nov 02 14:54:56 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 02 14:54:56 minidsp-shd volumio[639]: Cannot find translation for source Presets Nov 02 14:54:56 minidsp-shd sudo[1144]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Nov 02 14:54:56 minidsp-shd sudo[1144]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:56 minidsp-shd systemd[1]: Started RAAT DAEMON. Nov 02 14:54:56 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:56+08:00" level=debug msg="completed keyexchange" Nov 02 14:54:56 minidsp-shd sudo[1144]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:57 minidsp-shd sudo[1150]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Nov 02 14:54:57 minidsp-shd sudo[1150]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:57 minidsp-shd systemd[1]: Started Volumio Bluetooth Module. Nov 02 14:54:57 minidsp-shd sudo[1150]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:57 minidsp-shd volumio[639]: info: Raat Daemon started successfully Nov 02 14:54:57 minidsp-shd volumio[639]: info: Shairport-Sync Started Nov 02 14:54:57 minidsp-shd volumio[639]: Error adding Membership: Error: addMembership EINVAL Nov 02 14:54:57 minidsp-shd volumio[639]: info: Shairport-Sync Started Nov 02 14:54:57 minidsp-shd sudo[1162]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth/* Nov 02 14:54:57 minidsp-shd sudo[1162]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:57 minidsp-shd volumio[639]: info: Shairport-Sync Started Nov 02 14:54:57 minidsp-shd volumiobt[1161]: /bin/chmod: cannot access '/var/lib/bluetooth/*': No such file or directory Nov 02 14:54:57 minidsp-shd sudo[1162]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:57 minidsp-shd volumio[639]: info: TidalConnect service stoped! Nov 02 14:54:57 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:57+08:00" level=debug msg="completed challenge" Nov 02 14:54:57 minidsp-shd volumio[639]: info: Volumio BT Module successfully started Nov 02 14:54:57 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Nov 02 14:54:57 minidsp-shd volumio[639]: info: Enabling external Volume Control Nov 02 14:54:57 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:57 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 14:54:57 minidsp-shd volumio[639]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 02 14:54:57 minidsp-shd volumio[639]: SPOTIFY: BQD3e3_zRwC9_G7y5RZf4Un49tLWjAeTIOYeF-9ft_dsolT1gajNBmTIq6Qw7DtN_5fdF-1ZX4qU-N4B2HmblYQo5sfogOmcRwRNJFUQtJsVTHjAS7ySGsIN7ql4xC4xjXVWgg2JfEc5-31iDZGwyHVtLYXd1CgoFFaZqDsUr_TfKBLKPi7sRDBY9zX8KuNXtpAjeh8YgIPatxGYIdipAqyYJqogFe6ciNqAgXQJ1wZTAc6wE-LuWH-9y1pQX6u1ZWC_nR2rKkQjKwtZaLUD9AJbaA Nov 02 14:54:57 minidsp-shd volumio[639]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 02 14:54:57 minidsp-shd volumio[639]: info: New Spotify access token = BQD3e3_zRwC9_G7y5RZf4Un49tLWjAeTIOYeF-9ft_dsolT1gajNBmTIq6Qw7DtN_5fdF-1ZX4qU-N4B2HmblYQo5sfogOmcRwRNJFUQtJsVTHjAS7ySGsIN7ql4xC4xjXVWgg2JfEc5-31iDZGwyHVtLYXd1CgoFFaZqDsUr_TfKBLKPi7sRDBY9zX8KuNXtpAjeh8YgIPatxGYIdipAqyYJqogFe6ciNqAgXQJ1wZTAc6wE-LuWH-9y1pQX6u1ZWC_nR2rKkQjKwtZaLUD9AJbaA Nov 02 14:54:57 minidsp-shd volumio[639]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 02 14:54:57 minidsp-shd volumio[639]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Nov 02 14:54:57 minidsp-shd volumio[639]: info: Executing endpoint restartRAATSocket Nov 02 14:54:57 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Nov 02 14:54:57 minidsp-shd sudo[1175]: 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.68.53/USB /mnt/NAS/USB Nov 02 14:54:57 minidsp-shd sudo[1175]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:57 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:57+08:00" level=debug msg="authenticated as 21mduk4js3hup4d45e2mxuhxy" Nov 02 14:54:57 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioGetState Nov 02 14:54:57 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:54:57 minidsp-shd sudo[1177]: 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.68.55/USB /mnt/NAS/USB Nov 02 14:54:57 minidsp-shd sudo[1177]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:57 minidsp-shd kernel: CIFS: Attempting to mount //192.168.68.53/USB Nov 02 14:54:57 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. Nov 02 14:54:57 minidsp-shd kernel: CIFS: Attempting to mount //192.168.68.55/USB Nov 02 14:54:57 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. Nov 02 14:54:57 minidsp-shd volumio[639]: error: Hi Res Audio Failed Login: [object Object] Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="authenticated as 21mduk4js3hup4d45e2mxuhxy" Nov 02 14:54:58 minidsp-shd volumio[639]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Nov 02 14:54:58 minidsp-shd volumio[639]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="dealer connection opened" Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="initializing zeroconf session, username: 21mduk4js3hup4d45e2mxuhxy" Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="received connection id: MzExOTNlNDYtZWI0NS00NmFlLTk3MzktOTIzYTAwZjkwYjIxK2RlYWxlcit0Y3A6Ly8wYWM5NDg0ZC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArRkEwNDYyN0FFNDZBMUM3NEU4OTBGNjg4NzJCQzVBMTAyRjNBMzBEOENBRkQ2REM2QTE0MjY0QjA3QTUyRjU2Nw==" Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 02 14:54:58 minidsp-shd sudo[1185]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Nov 02 14:54:58 minidsp-shd sudo[1185]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:58 minidsp-shd systemd[1]: Started Volumio Tidal Connect Service. Nov 02 14:54:58 minidsp-shd volumio[639]: info: Access Token successfully retrieved Nov 02 14:54:58 minidsp-shd sudo[1185]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="put connect state because NEW_DEVICE" Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="autoplay enabled: false" Nov 02 14:54:58 minidsp-shd sudo[1188]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall pulseaudio Nov 02 14:54:58 minidsp-shd sudo[1188]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 02 14:54:58 minidsp-shd volumio[639]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 3 Nov 02 14:54:58 minidsp-shd volumiobt[1161]: pulseaudio: no process found Nov 02 14:54:58 minidsp-shd sudo[1188]: pam_unix(sudo:session): session closed for user root Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 02 14:54:58 minidsp-shd go-librespot[1107]: time="2024-11-02T14:54:58+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 342" Nov 02 14:54:58 minidsp-shd dbus-daemon[452]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.12' (uid=1000 pid=1194 comm="/usr/bin/pulseaudio --high-priority=true ") Nov 02 14:54:58 minidsp-shd systemd[1]: Starting RealtimeKit Scheduling Policy Service... Nov 02 14:54:58 minidsp-shd volumio[639]: info: CoreStateMachine::pushState Nov 02 14:54:58 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:54:58 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 02 14:54:58 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioPushState Nov 02 14:54:58 minidsp-shd volumio[639]: error: Help! Some callbacks for volumioPushState are crashing! Nov 02 14:54:58 minidsp-shd volumio[639]: error: Cannot read property 'sendVolumeMute' of undefined Nov 02 14:54:58 minidsp-shd dbus-daemon[452]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1' Nov 02 14:54:58 minidsp-shd systemd[1]: Started RealtimeKit Scheduling Policy Service. Nov 02 14:54:58 minidsp-shd rtkit-daemon[1195]: Successfully called chroot. Nov 02 14:54:58 minidsp-shd volumio[639]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 02 14:54:58 minidsp-shd rtkit-daemon[1195]: Successfully dropped privileges. Nov 02 14:54:58 minidsp-shd rtkit-daemon[1195]: Successfully limited resources. Nov 02 14:54:58 minidsp-shd rtkit-daemon[1195]: Running. Nov 02 14:54:58 minidsp-shd dbus-daemon[452]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.13' (uid=0 pid=1195 comm="/usr/lib/rtkit/rtkit-daemon ") Nov 02 14:54:58 minidsp-shd rtkit-daemon[1195]: Watchdog thread running. Nov 02 14:54:58 minidsp-shd rtkit-daemon[1195]: Canary thread running. Nov 02 14:54:58 minidsp-shd systemd[1]: Starting Authorization Manager... Nov 02 14:54:58 minidsp-shd volumio[639]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 02 14:54:58 minidsp-shd polkitd[1198]: started daemon version 0.105 using authority implementation `local' version `0.105' Nov 02 14:54:58 minidsp-shd dbus-daemon[452]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' Nov 02 14:54:58 minidsp-shd systemd[1]: Started Authorization Manager. Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioGetState Nov 02 14:54:59 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:54:59 minidsp-shd volumio[639]: info: Successfully retrieved User Session From TIDAL Nov 02 14:54:59 minidsp-shd volumio[639]: info: go-librespot daemon successfully initialized Nov 02 14:54:59 minidsp-shd volumio[639]: SPOTIFY: User informations: {"country":"SG","display_name":"Peng Keng Koh","email":"koh_peng_keng@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/21mduk4js3hup4d45e2mxuhxy"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/21mduk4js3hup4d45e2mxuhxy","id":"21mduk4js3hup4d45e2mxuhxy","images":[{"height":300,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=10213933331597580&height=300&width=300&ext=1733122495&hash=AbaXjgmqJZljszh72TC8kwir","width":300},{"height":64,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=10213933331597580&height=50&width=50&ext=1733122495&hash=AbaruMoMwqqo6jBR4gtmAWmD","width":64}],"product":"premium","type":"user","uri":"spotify:user:21mduk4js3hup4d45e2mxuhxy"} Nov 02 14:54:59 minidsp-shd volumio[639]: info: Spotify Successfully logged in Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 02 14:54:59 minidsp-shd volumio[639]: info: [1730530499265] CoreMusicLibrary::Adding element Spotify Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 02 14:54:59 minidsp-shd volumio[639]: Cannot find translation for source Presets Nov 02 14:54:59 minidsp-shd volumio[639]: Cannot find translation for source Spotify Nov 02 14:54:59 minidsp-shd volumio[639]: info: Executing endpoint tc_getconfig Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Nov 02 14:54:59 minidsp-shd vtcs[1187]: STARTING TidalConnect services, version: 1.3.0.19 Nov 02 14:54:59 minidsp-shd volumio[639]: info: Successfully retrieved User Subscription From TIDAL Nov 02 14:54:59 minidsp-shd volumio[639]: info: Adding TIDAL to Browse Sources Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 02 14:54:59 minidsp-shd volumio[639]: info: [1730530499548] CoreMusicLibrary::Adding element TIDAL Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 02 14:54:59 minidsp-shd volumio[639]: Cannot find translation for source Presets Nov 02 14:54:59 minidsp-shd volumio[639]: Cannot find translation for source Spotify Nov 02 14:54:59 minidsp-shd volumio[639]: Cannot find translation for source TIDAL Nov 02 14:54:59 minidsp-shd volumio[639]: info: Stopping AccessToken refresher cron Nov 02 14:54:59 minidsp-shd vtcs[1187]: STARTED TidalConnect services. Nov 02 14:54:59 minidsp-shd volumio[639]: info: AccessToken refresher cron started Nov 02 14:54:59 minidsp-shd volumio[639]: info: Adding TIDAL REST API Endpoints Nov 02 14:54:59 minidsp-shd volumio[639]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreStateMachine::pushState Nov 02 14:54:59 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioPushState Nov 02 14:54:59 minidsp-shd volumio[639]: error: Help! Some callbacks for volumioPushState are crashing! Nov 02 14:54:59 minidsp-shd volumio[639]: error: Cannot read property 'sendVolumeMute' of undefined Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: raat , updateRoonVolume Nov 02 14:54:59 minidsp-shd dbus-daemon[452]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.33' (uid=1000 pid=1194 comm="/usr/bin/pulseaudio --high-priority=true ") Nov 02 14:54:59 minidsp-shd systemd[1]: Starting Bluetooth service... Nov 02 14:54:59 minidsp-shd volumio[639]: info: Executing endpoint tc_connect Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Nov 02 14:54:59 minidsp-shd volumio[639]: info: Connecting to TidalConnect Nov 02 14:54:59 minidsp-shd volumio[639]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 02 14:54:59 minidsp-shd pulseaudio[1194]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Nov 02 14:54:59 minidsp-shd pulseaudio[1194]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Nov 02 14:54:59 minidsp-shd volumiobt[1161]: Applying permissions Nov 02 14:54:59 minidsp-shd volumiobt[1161]: Setting BT discoverable and pairable Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreCommandRouter::servicePushState Nov 02 14:54:59 minidsp-shd volumio[639]: info: CoreStateMachine::pushState Nov 02 14:54:59 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:55:00 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioPushState Nov 02 14:55:00 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:55:00 minidsp-shd volumio[639]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Nov 02 14:55:00 minidsp-shd bluetoothd[1209]: Bluetooth daemon 5.23 Nov 02 14:55:00 minidsp-shd volumio[639]: info: CoreCommandRouter::servicePushState Nov 02 14:55:00 minidsp-shd volumio[639]: info: CoreStateMachine::pushState Nov 02 14:55:00 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:55:00 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioPushState Nov 02 14:55:00 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:55:00 minidsp-shd volumio[639]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Nov 02 14:55:00 minidsp-shd dbus-daemon[452]: [system] Successfully activated service 'org.bluez' Nov 02 14:55:00 minidsp-shd systemd[1]: Started Bluetooth service. Nov 02 14:55:00 minidsp-shd bluetoothd[1209]: Starting SDP server Nov 02 14:55:00 minidsp-shd bluetoothd[1209]: kernel lacks bnep-protocol support Nov 02 14:55:00 minidsp-shd bluetoothd[1209]: System does not support network plugin Nov 02 14:55:00 minidsp-shd bluetoothd[1209]: Bluetooth management interface 1.14 initialized Nov 02 14:55:00 minidsp-shd dbus-daemon[452]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.35' (uid=0 pid=1209 comm="/usr/local/libexec/bluetooth/bluetoothd ") Nov 02 14:55:00 minidsp-shd pulseaudio[1194]: 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 Nov 02 14:55:00 minidsp-shd volumiobt[1161]: [38B blob data] Nov 02 14:55:00 minidsp-shd volumiobt[1161]: Invalid command Nov 02 14:55:00 minidsp-shd volumiobt[1161]: [bluetooth]# agent on Nov 02 14:55:00 minidsp-shd volumiobt[1161]: [bluetooth]# discoverable on Nov 02 14:55:00 minidsp-shd volumiobt[1161]: No default controller available Nov 02 14:55:00 minidsp-shd volumiobt[1161]: [bluetooth]# pairable on Nov 02 14:55:00 minidsp-shd volumiobt[1161]: No default controller available Nov 02 14:55:00 minidsp-shd volumiobt[1161]: [bluetooth]# agent NoInputNoOutput Nov 02 14:55:00 minidsp-shd volumiobt[1161]: Failed to register agent object Nov 02 14:55:00 minidsp-shd volumiobt[1161]: [bluetooth]# default-agent Nov 02 14:55:00 minidsp-shd volumiobt[1161]: No agent is registered Nov 02 14:55:00 minidsp-shd volumiobt[1161]: [bluetooth]# quit Nov 02 14:55:00 minidsp-shd volumiobt[1161]: [61B blob data] Nov 02 14:55:00 minidsp-shd volumiobt[1161]: [62B blob data] Nov 02 14:55:00 minidsp-shd systemd[1]: Starting Hostname Service... Nov 02 14:55:00 minidsp-shd volumio[639]: ------------------------------------ BT MESSAGE: BT STATUS: running Nov 02 14:55:00 minidsp-shd kernel: CIFS VFS: Error connecting to socket. Aborting operation. Nov 02 14:55:00 minidsp-shd kernel: CIFS VFS: cifs_mount failed w/return code = -111 Nov 02 14:55:00 minidsp-shd sudo[1175]: pam_unix(sudo:session): session closed for user root Nov 02 14:55:00 minidsp-shd volumio[639]: info: Cannot mount NAS USB at system boot, trial number 2 ,retrying in 5 seconds Nov 02 14:55:00 minidsp-shd dbus-daemon[452]: [system] Successfully activated service 'org.freedesktop.hostname1' Nov 02 14:55:00 minidsp-shd systemd[1]: Started Hostname Service. Nov 02 14:55:01 minidsp-shd volumio[639]: info: TidalConnect service started! Nov 02 14:55:02 minidsp-shd mpd[1064]: Nov 02 14:55 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 02 14:55:02 minidsp-shd volumio[639]: info: Initializing connection to go-librespot Websocket Nov 02 14:55:02 minidsp-shd volumio-remote-updater[456]: [2024-11-02 14:55:02] [connect] Successful connection Nov 02 14:55:02 minidsp-shd volumio-remote-updater[456]: [2024-11-02 14:55:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1730530502 101 Nov 02 14:55:02 minidsp-shd volumio[639]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 4 Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="new websocket client" Nov 02 14:55:02 minidsp-shd volumio[639]: info: Connection to go-librespot Websocket established Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="handling transfer player command from 6fec1add867b1a2b4540b787f8f833f490937ed9" Nov 02 14:55:02 minidsp-shd systemd[1]: Started Music Player Daemon. Nov 02 14:55:02 minidsp-shd volumio[639]: Upnp client error: Error: This socket has been ended by the other party Nov 02 14:55:02 minidsp-shd sudo[1060]: pam_unix(sudo:session): session closed for user root Nov 02 14:55:02 minidsp-shd sudo[1050]: pam_unix(sudo:session): session closed for user root Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E4zpqf0Ot6Dwx" Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E4zpqf0Ot6Dwx" Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="shuffled context with seed 16767640603773441194 (len: 50, keep: 42)" Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="loading track (paused: false, position: 308505ms)" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:02 minidsp-shd volumio[639]: info: Completed starting Core Plugins Nov 02 14:55:02 minidsp-shd volumio[639]: info: ------------------------------------------- Nov 02 14:55:02 minidsp-shd volumio[639]: info: ----- MyVolumio plugins startup ---- Nov 02 14:55:02 minidsp-shd volumio[639]: info: ------------------------------------------- Nov 02 14:55:02 minidsp-shd volumio[639]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 02 14:55:02 minidsp-shd volumio[639]: info: MPD running with PID1064 Nov 02 14:55:02 minidsp-shd volumio[639]: ,establishing connection Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=trace msg="emitting websocket event: will_play" Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="selected format OGG_VORBIS_320 (f6ac15907c85666bda12cee1ff0bbad35f0ce431)" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="requested aes key for file f6ac15907c85666bda12cee1ff0bbad35f0ce431, gid: 2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:02 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:02+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2052" Nov 02 14:55:02 minidsp-shd volumio[639]: error: MPD error: The expression evaluated to a falsy value: Nov 02 14:55:02 minidsp-shd volumio[639]: assert.ok(self.idling) Nov 02 14:55:02 minidsp-shd volumio[639]: error: The expression evaluated to a falsy value: Nov 02 14:55:02 minidsp-shd volumio[639]: assert.ok(self.idling) Nov 02 14:55:02 minidsp-shd volumio[639]: error: MPD error: The expression evaluated to a falsy value: Nov 02 14:55:02 minidsp-shd volumio[639]: assert.ok(self.idling) Nov 02 14:55:02 minidsp-shd volumio[639]: error: The expression evaluated to a falsy value: Nov 02 14:55:02 minidsp-shd volumio[639]: assert.ok(self.idling) Nov 02 14:55:02 minidsp-shd volumio[639]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2wzXhxWPX0aODraKNXoJYY","play_origin":"playlist"}} Nov 02 14:55:02 minidsp-shd volumio[639]: error: updateQueue error: null Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched first chunk of 27, total size is 13812612 bytes" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1482" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 1/26, size: 524288" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 26/26, size: 181124" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 3/26, size: 524288" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 24/26, size: 524288" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 25/26, size: 524288" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 23/26, size: 524288" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 2/26, size: 524288" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=trace msg="seek to 308505ms (diff: 70ms, samples: 13605070, bytes: 12546045)" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5804 us, period size = 256 frames, buffer time = 92879 us, buffer size = 4096 frames, periods per buffer = 16 frames" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="created new output device" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=info msg="loaded track \"後來\" (paused: false, position: 308505ms, duration: 341400ms, prefetched: false)" uri="spotify:track:2wzXhxWPX0aODraKNXoJYY" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=trace msg="emitting websocket event: metadata" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="prefetching next track" uri="spotify:track:0rUiL3L1lurq2lzcfUCSji" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=trace msg="emitting websocket event: active" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="sending successful reply for dealer request" Nov 02 14:55:03 minidsp-shd volumio[639]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2wzXhxWPX0aODraKNXoJYY","name":"後來","artist_names":["Rene Liu"],"album_name":"我等你","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02794c74a4950a105ffe3be4ed","position":308505,"duration":341400,"release_date":"year:2000 month:1 day:7","track_number":2,"disc_number":1}} Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 02 14:55:03 minidsp-shd volumio[639]: SPOTIFY: received: {"type":"active","data":null} Nov 02 14:55:03 minidsp-shd volumio[639]: info: Aligning Spotify Volume to Volumio Volume Nov 02 14:55:03 minidsp-shd volumio[639]: info: CoreCommandRouter::volumioGetState Nov 02 14:55:03 minidsp-shd volumio[639]: info: CorePlayQueue::getTrack 0 Nov 02 14:55:03 minidsp-shd volumio[639]: info: Setting Spotify Volume from Volumio: 100 Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="selected format OGG_VORBIS_320 (f3b49e3095ce863a423d444689621dbceb6da36f)" uri="spotify:track:0rUiL3L1lurq2lzcfUCSji" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="requested aes key for file f3b49e3095ce863a423d444689621dbceb6da36f, gid: 0rUiL3L1lurq2lzcfUCSji" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=trace msg="emitting websocket event: playing" Nov 02 14:55:03 minidsp-shd volumio[639]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2wzXhxWPX0aODraKNXoJYY","play_origin":"playlist"}} Nov 02 14:55:03 minidsp-shd volumio[639]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 02 14:55:03 minidsp-shd volumio[639]: TypeError: Cannot read property 'service' of undefined Nov 02 14:55:03 minidsp-shd volumio[639]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Nov 02 14:55:03 minidsp-shd volumio[639]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Nov 02 14:55:03 minidsp-shd volumio[639]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Nov 02 14:55:03 minidsp-shd volumio[639]: at WebSocket.emit (events.js:400:28) Nov 02 14:55:03 minidsp-shd volumio[639]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 02 14:55:03 minidsp-shd volumio[639]: at Receiver.emit (events.js:400:28) Nov 02 14:55:03 minidsp-shd volumio[639]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 02 14:55:03 minidsp-shd volumio[639]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 02 14:55:03 minidsp-shd volumio[639]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 02 14:55:03 minidsp-shd volumio[639]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 02 14:55:03 minidsp-shd volumio[639]: at writeOrBuffer (internal/streams/writable.js:358:12) Nov 02 14:55:03 minidsp-shd volumio[639]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Nov 02 14:55:03 minidsp-shd volumio[639]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Nov 02 14:55:03 minidsp-shd volumio[639]: at Socket.emit (events.js:400:28) Nov 02 14:55:03 minidsp-shd volumio[639]: at addChunk (internal/streams/readable.js:293:12) Nov 02 14:55:03 minidsp-shd volumio[639]: at readableAddChunk (internal/streams/readable.js:267:9) Nov 02 14:55:03 minidsp-shd volumio[639]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched first chunk of 17, total size is 8631240 bytes" uri="spotify:track:0rUiL3L1lurq2lzcfUCSji" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0rUiL3L1lurq2lzcfUCSji" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=info msg="prefetched track \"味道\" (duration: 237333ms)" uri="spotify:track:0rUiL3L1lurq2lzcfUCSji" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:0rUiL3L1lurq2lzcfUCSji" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:0rUiL3L1lurq2lzcfUCSji" Nov 02 14:55:03 minidsp-shd go-librespot[1107]: time="2024-11-02T14:55:03+08:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:0rUiL3L1lurq2lzcfUCSji" Nov 02 14:55:04 minidsp-shd kernel: CIFS VFS: Error connecting to socket. Aborting operation. Nov 02 14:55:04 minidsp-shd kernel: CIFS VFS: cifs_mount failed w/return code = -113 Nov 02 14:55:04 minidsp-shd sudo[1177]: pam_unix(sudo:session): session closed for user root Nov 02 14:55:04 minidsp-shd sudo[1277]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-02 14:54 Nov 02 14:55:04 minidsp-shd sudo[1277]: 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"