Dec 17 00:07:02 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Dec 17 00:07:02 pioneer-sx-950 volumio[1366]: info: MyVolumio login type: Token Dec 17 00:07:03 pioneer-sx-950 volumio[1366]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 17 00:07:03 pioneer-sx-950 volumio[1366]: info: MyVolumio token set successfully Dec 17 00:07:03 pioneer-sx-950 volumio[1366]: info: MYVOLUMIO: Adding device Dec 17 00:07:03 pioneer-sx-950 volumio[1366]: info: MYVOLUMIO: Evaluating Server Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: MyVolumio Plan changed: premium Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: Removing browser output: myVolumio user plan is not superstar Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: Removing audio output: Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: MYVOLUMIO: Adding device Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: MYVOLUMIO: Evaluating Server Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: Remote config written successfully Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: Starting Tunnel 1 Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: Starting Tunnel Connection Checker Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: MYVolumio Device enabled Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: MyVolumio status changed Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: Streaming services startup Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: Starting Streaming Daemon Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: Setting Geolocation for MyVolumio to eu4 Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:04 pioneer-sx-950 sudo[4097]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 17 00:07:04 pioneer-sx-950 sudo[4097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: error: [MyVolumio PluginManager] Could not read cache file: ENOENT: no such file or directory, open '/data/myvolumio/cache.data' Dec 17 00:07:04 pioneer-sx-950 sudo[4097]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: error: Cannot start Volumio Streaming Daemon Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 17 00:07:04 pioneer-sx-950 volumio[1366]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: Setting Geolocation for MyVolumio to eu10 Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: Successfully Added MyVolumio device Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: Successfully Added MyVolumio device Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: Received Get System Info Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: Discovery: Getting this device information Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CorePlayQueue::getTrack 0 Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: Updating MyVolumio device info Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:05 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:06 pioneer-sx-950 volumio[1366]: info: Updating MyVolumio device info Dec 17 00:07:06 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:06 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:06 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:06 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Dec 17 00:07:06 pioneer-sx-950 volumio[1366]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Dec 17 00:07:06 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Dec 17 00:07:09 pioneer-sx-950 sudo[4103]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Dec 17 00:07:09 pioneer-sx-950 sudo[4103]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:09 pioneer-sx-950 sudo[4103]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: MRS: MultiRoom plugin initialized Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: MRS: STOPPING SNAPCLIENT Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: MRS: Snap server stop Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: MRS: STOPPING volumioStreaming Dec 17 00:07:09 pioneer-sx-950 sudo[4120]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Dec 17 00:07:09 pioneer-sx-950 sudo[4120]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:09 pioneer-sx-950 sudo[4122]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Dec 17 00:07:09 pioneer-sx-950 sudo[4122]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Dec 17 00:07:09 pioneer-sx-950 sudo[4124]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Dec 17 00:07:09 pioneer-sx-950 sudo[4124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Dec 17 00:07:09 pioneer-sx-950 sudo[4127]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 17 00:07:09 pioneer-sx-950 sudo[4127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:09 pioneer-sx-950 sudo[4127]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Dec 17 00:07:09 pioneer-sx-950 sudo[4120]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:09 pioneer-sx-950 sudo[4122]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:09 pioneer-sx-950 sudo[4124]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Dec 17 00:07:09 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Preparing to generate the ALSA configuration file Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Successfully Updated MyVolumio device Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Successfully Updated MyVolumio device Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: MRS: Removed streaming files Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: MRS: volumioStreaming STOPPED Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: MRS: SNAPSERVER STOPPED Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: MRS: SNAPCLIENT STOPPED Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Asound.conf file unchanged, so no further update is needed Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Output device has changed, restarting MPD Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Output device has changed, restarting Shairport Sync Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:10 pioneer-sx-950 sudo[4132]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 17 00:07:10 pioneer-sx-950 sudo[4132]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:10 pioneer-sx-950 sudo[4134]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 17 00:07:10 pioneer-sx-950 sudo[4132]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:10 pioneer-sx-950 sudo[4134]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: ------------------------------------ BT MESSAGE: [FUNC] onStart Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: ------------------------------------ BT MESSAGE: [metaCache] Created directory: /tmp/bluetooth-cache/ Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Dec 17 00:07:10 pioneer-sx-950 systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output for this device Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Adding audio output: Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Adding audio output: Dec 17 00:07:10 pioneer-sx-950 systemd[1]: mpd.service: Deactivated successfully. Dec 17 00:07:10 pioneer-sx-950 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 17 00:07:10 pioneer-sx-950 systemd[1]: mpd.service: Consumed 3.139s CPU time. Dec 17 00:07:10 pioneer-sx-950 systemd[1]: mpd.socket: Deactivated successfully. Dec 17 00:07:10 pioneer-sx-950 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 17 00:07:10 pioneer-sx-950 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:10 pioneer-sx-950 bluetoothd[988]: Path / reserved for Adv Monitor app :1.38 Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Adding METAVOLUMIO REST API Endpoints Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Dec 17 00:07:10 pioneer-sx-950 bluetoothd[988]: Adv Monitor app :1.38 disconnected from D-Bus Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Preparing CD Folders Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Adding CD REST API Endpoints Dec 17 00:07:10 pioneer-sx-950 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Starting UDEV Watcher for CD Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: Detecting CD presence with UDEV Dec 17 00:07:10 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Dec 17 00:07:10 pioneer-sx-950 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 17 00:07:10 pioneer-sx-950 sudo[4149]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 17 00:07:10 pioneer-sx-950 sudo[4149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 17 00:07:10 pioneer-sx-950 sudo[4149]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:13 pioneer-sx-950 mpd[4154]: 2025-12-17T00:07:13 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 17 00:07:13 pioneer-sx-950 systemd[1]: Started mpd.service - Music Player Daemon. Dec 17 00:07:13 pioneer-sx-950 sudo[4134]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: warn: [cd-plugin] cdspeedctl: device or media not ready Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Adding inputs REST Endpoints Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Scanning Audio Inputs Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Checking against Known Cards name Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Adding Server instance for streaming Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: error: Hi Res Audio Failed Login: Missing Login Data Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Adding HIGHRESAUDIO REST API Endpoints Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: QobuzConnect: Starting Qobuz Connect socket and service Dec 17 00:07:15 pioneer-sx-950 sudo[4179]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 17 00:07:15 pioneer-sx-950 sudo[4179]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:15 pioneer-sx-950 sudo[4186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 17 00:07:15 pioneer-sx-950 sudo[4186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Dec 17 00:07:15 pioneer-sx-950 sudo[4179]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Adding TIDAL REST API Endpoints Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Stopping AccessToken refresher cron for QOBUZ Dec 17 00:07:15 pioneer-sx-950 sudo[4186]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:15 pioneer-sx-950 sudo[4189]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: AccessToken refresher cron started for QOBUZ Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: Adding QOBUZ REST API Endpoints Dec 17 00:07:15 pioneer-sx-950 sudo[4189]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: MRS: Getting audio outputs on start Dec 17 00:07:15 pioneer-sx-950 volumio[1366]: info: MRS: Requesting all other devices output Dec 17 00:07:16 pioneer-sx-950 systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 17 00:07:16 pioneer-sx-950 sudo[4189]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: MPD Permissions set Dec 17 00:07:16 pioneer-sx-950 sudo[4199]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Dec 17 00:07:16 pioneer-sx-950 sudo[4199]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:16 pioneer-sx-950 sudo[4202]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 17 00:07:16 pioneer-sx-950 sudo[4202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:16 pioneer-sx-950 sudo[4205]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 17 00:07:16 pioneer-sx-950 sudo[4205]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:16 pioneer-sx-950 sudo[4202]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: MRS: Adding multiroomSync output Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: Adding audio output: Dec 17 00:07:16 pioneer-sx-950 sudo[4205]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output Dec 17 00:07:16 pioneer-sx-950 sudo[4208]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:16 pioneer-sx-950 sudo[4208]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: error: updateQueue error: null Dec 17 00:07:16 pioneer-sx-950 systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Dec 17 00:07:16 pioneer-sx-950 sudo[4199]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:16 pioneer-sx-950 volumiobt[4217]: INFO [BTSTART] Ensuring Bluetooth directory exists... Dec 17 00:07:16 pioneer-sx-950 systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 17 00:07:16 pioneer-sx-950 systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 17 00:07:16 pioneer-sx-950 sudo[4218]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Dec 17 00:07:16 pioneer-sx-950 sudo[4218]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:16 pioneer-sx-950 systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Dec 17 00:07:16 pioneer-sx-950 sudo[4218]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: Executing endpoint qc_getconfig Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 17 00:07:16 pioneer-sx-950 sudo[4208]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:16 pioneer-sx-950 sudo[4221]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Dec 17 00:07:16 pioneer-sx-950 sudo[4221]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:16 pioneer-sx-950 sudo[4221]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:16 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:16.549 [4197.4197] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 17 00:07:16 pioneer-sx-950 volumiobt[4230]: INFO [BTSTART] Powering on Bluetooth if needed... Dec 17 00:07:16 pioneer-sx-950 autossh[4222]: port set to 0, monitoring disabled Dec 17 00:07:16 pioneer-sx-950 autossh[4222]: starting ssh (count 1) Dec 17 00:07:16 pioneer-sx-950 autossh[4222]: ssh child pid is 4231 Dec 17 00:07:16 pioneer-sx-950 bluetoothd[988]: Adv Monitor app :1.40 disconnected from D-Bus Dec 17 00:07:16 pioneer-sx-950 volumiobt[4234]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: Remote SSH Started Dec 17 00:07:16 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:16.818 [4197.4197] INFO VolumeManager: [0x182b228]: Setting new playback volume: 75 Dec 17 00:07:16 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:16.818 [4197.4197] INFO VolumeManager: [0x182b228]: Setting new mute state: 0 Dec 17 00:07:16 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:16.818 [4197.4197] INFO QobuzConnect: [0x182bbf8]: Client initialized! Dec 17 00:07:16 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:16.818 [4197.4197] INFO SampleApp: Starting Avahi advertising, name: Pioneer SX-950, service name: _qobuz-connect._tcp Dec 17 00:07:16 pioneer-sx-950 volumiobt[4235]: [176B blob data] Dec 17 00:07:16 pioneer-sx-950 volumiobt[4235]: [157B blob data] Dec 17 00:07:16 pioneer-sx-950 volumiobt[4235]: [157B blob data] Dec 17 00:07:16 pioneer-sx-950 volumiobt[4235]: [157B blob data] Dec 17 00:07:16 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:16.859 [4197.4197] INFO LocalConfigManager: [0x182ab08]: Starting Local Configuration server Dec 17 00:07:16 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:16.859 [4197.4197] INFO SampleApp: Starting Local configuration server Dec 17 00:07:16 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:16.860 [4197.4197] INFO SampleApp: Playback volume changed: 75 Dec 17 00:07:16 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:16.860 [4197.4197] INFO SampleApp: Connected to UNIX socket client 0x1815818 Dec 17 00:07:16 pioneer-sx-950 volumiobt[4235]: [113B blob data] Dec 17 00:07:16 pioneer-sx-950 volumiobt[4235]: [bluetoothctl]> discoverable on Dec 17 00:07:16 pioneer-sx-950 volumiobt[4235]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended Dec 17 00:07:16 pioneer-sx-950 volumiobt[4235]: [bluetoothctl]> pairable on Dec 17 00:07:16 pioneer-sx-950 bluetoothd[988]: Path / reserved for Adv Monitor app :1.41 Dec 17 00:07:16 pioneer-sx-950 bluetoothd[988]: Adv Monitor app :1.41 disconnected from D-Bus Dec 17 00:07:16 pioneer-sx-950 volumiobt[4235]: [bluetoothctl]> Dec 17 00:07:16 pioneer-sx-950 volumiobt[4239]: INFO [BTSTART] Registering Bluetooth agent... Dec 17 00:07:16 pioneer-sx-950 volumiobt[4240]: [NEW] Media /org/bluez/hci0 Dec 17 00:07:16 pioneer-sx-950 volumiobt[4240]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Dec 17 00:07:16 pioneer-sx-950 volumiobt[4240]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Dec 17 00:07:16 pioneer-sx-950 volumiobt[4240]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioStop Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::stop Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 17 00:07:16 pioneer-sx-950 volumio[1366]: info: Starting Shairport Sync Dec 17 00:07:17 pioneer-sx-950 bluetoothd[988]: Adv Monitor app :1.43 disconnected from D-Bus Dec 17 00:07:17 pioneer-sx-950 volumiossh-tunnel[4231]: Warning: Permanently added '[eu10.myvolumio.org]:2222' (RSA) to the list of known hosts. Dec 17 00:07:17 pioneer-sx-950 volumiobt[4241]: No agent is registered Dec 17 00:07:17 pioneer-sx-950 volumiobt[4241]: [NEW] Media /org/bluez/hci0 Dec 17 00:07:17 pioneer-sx-950 volumiobt[4241]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Dec 17 00:07:17 pioneer-sx-950 volumiobt[4241]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Dec 17 00:07:17 pioneer-sx-950 volumiobt[4241]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Dec 17 00:07:17 pioneer-sx-950 sudo[4243]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 17 00:07:17 pioneer-sx-950 sudo[4243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:17 pioneer-sx-950 sudo[4245]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 17 00:07:17 pioneer-sx-950 sudo[4245]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:17 pioneer-sx-950 bluetoothd[988]: Adv Monitor app :1.44 disconnected from D-Bus Dec 17 00:07:17 pioneer-sx-950 volumiobt[4249]: INFO [BTSTART] Agent registered successfully. Dec 17 00:07:17 pioneer-sx-950 sudo[4245]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:17 pioneer-sx-950 volumiobt[4251]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Dec 17 00:07:17 pioneer-sx-950 sudo[4247]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 17 00:07:17 pioneer-sx-950 sudo[4247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: verbose: New Socket.io Connection to 192.168.1.33 from 192.168.1.28 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:17 pioneer-sx-950 sudo[4247]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Preparing to generate the ALSA configuration file Dec 17 00:07:17 pioneer-sx-950 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 17 00:07:17 pioneer-sx-950 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 17 00:07:17 pioneer-sx-950 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 17 00:07:17 pioneer-sx-950 systemd[1]: shairport-sync.service: Consumed 2.479s CPU time. Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 17 00:07:17 pioneer-sx-950 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 17 00:07:17 pioneer-sx-950 sudo[4243]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: verbose: New Socket.io Connection to 192.168.1.33 from 192.168.1.28 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Asound.conf file unchanged, so no further update is needed Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Output device has changed, restarting MPD Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Output device has changed, restarting Shairport Sync Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:17 pioneer-sx-950 sudo[4256]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 17 00:07:17 pioneer-sx-950 sudo[4256]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:17 pioneer-sx-950 sudo[4258]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 17 00:07:17 pioneer-sx-950 sudo[4256]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:17 pioneer-sx-950 sudo[4258]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: QobuzConnect: setDeactiveState invoked Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:17 pioneer-sx-950 systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Preparing to generate the ALSA configuration file Dec 17 00:07:17 pioneer-sx-950 systemd[1]: mpd.service: Deactivated successfully. Dec 17 00:07:17 pioneer-sx-950 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 17 00:07:17 pioneer-sx-950 systemd[1]: mpd.service: Consumed 2.998s CPU time. Dec 17 00:07:17 pioneer-sx-950 systemd[1]: mpd.socket: Deactivated successfully. Dec 17 00:07:17 pioneer-sx-950 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 17 00:07:17 pioneer-sx-950 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Shairport-Sync Started Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:17 pioneer-sx-950 sudo[4287]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 17 00:07:17 pioneer-sx-950 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 17 00:07:17 pioneer-sx-950 sudo[4287]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:17 pioneer-sx-950 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Reading ALSA contributions from plugins. Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: MPD Permissions set Dec 17 00:07:17 pioneer-sx-950 sudo[4287]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Received Get System Info Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Discovery: Getting this device information Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetVisibleSources Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Received Get System Info Dec 17 00:07:17 pioneer-sx-950 sudo[4290]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Discovery: Getting this device information Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Listing playlists Dec 17 00:07:17 pioneer-sx-950 sudo[4290]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:17 pioneer-sx-950 volumio[1366]: info: Received Get System Info Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: Discovery: Getting this device information Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:18 pioneer-sx-950 sudo[4288]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 17 00:07:18 pioneer-sx-950 sudo[4288]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 17 00:07:18 pioneer-sx-950 systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 17 00:07:18 pioneer-sx-950 sudo[4288]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:18 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:18.065 [4197.4197] INFO SampleApp: Stopping Local configuration server Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.RG5zunBDuuVZmqaEuaj8GWI7P002.c58fb4b88f86da7cf1595319df2df740.state.status' Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: Starting Shairport Sync Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: Asound.conf file written Dec 17 00:07:18 pioneer-sx-950 sudo[4301]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 17 00:07:18 pioneer-sx-950 sudo[4301]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:18 pioneer-sx-950 sudo[4305]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 17 00:07:18 pioneer-sx-950 sudo[4305]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:18 pioneer-sx-950 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 17 00:07:18 pioneer-sx-950 sudo[4305]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:18 pioneer-sx-950 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 17 00:07:18 pioneer-sx-950 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 17 00:07:18 pioneer-sx-950 systemd[1]: shairport-sync.service: Consumed 1.125s CPU time. Dec 17 00:07:18 pioneer-sx-950 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: No state is present for card b1 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: /usr/share/alsa/init/bcm2835:14: control element not found Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: No state is present for card b1 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: No state is present for card Headphones Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: /usr/share/alsa/init/bcm2835:20: control element not found Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: No state is present for card Headphones Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: No state is present for card Boss2 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: Found hardware: "Allo_Boss2" "" "" "" "" Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: Hardware is initialized using a generic method Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: No state is present for card Boss2 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: Output device has changed, restarting MPD Dec 17 00:07:18 pioneer-sx-950 sudo[4301]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:18 pioneer-sx-950 volumiobt[4252]: INFO:a2dp-agent:Connecting to system bus. Dec 17 00:07:18 pioneer-sx-950 volumiobt[4252]: INFO:a2dp-agent:Found Bluetooth adapter at: /org/bluez/hci0 Dec 17 00:07:18 pioneer-sx-950 volumiobt[4252]: INFO:a2dp-agent:Enabling infinite discovery on adapter. Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: Output device has changed, restarting Shairport Sync Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:18 pioneer-sx-950 sudo[4312]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 17 00:07:18 pioneer-sx-950 volumiobt[4252]: INFO:a2dp-agent:Registering agent. Dec 17 00:07:18 pioneer-sx-950 sudo[4312]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:18 pioneer-sx-950 volumiobt[4252]: INFO:a2dp-agent:Searching for MediaPlayer1 interface... Dec 17 00:07:18 pioneer-sx-950 volumiobt[4252]: WARNING:a2dp-agent:No active MediaPlayer1 found. Metadata updates won't work. Dec 17 00:07:18 pioneer-sx-950 qobuz-connect[4197]: 20251217 00:07:18.874 [4197.4197] INFO SampleApp: shat down connection on UNIX socket Dec 17 00:07:18 pioneer-sx-950 sudo[4312]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:18 pioneer-sx-950 systemd[1]: qobuz-connect.service: Deactivated successfully. Dec 17 00:07:18 pioneer-sx-950 sudo[4327]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 17 00:07:18 pioneer-sx-950 systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Dec 17 00:07:18 pioneer-sx-950 sudo[4327]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: QobuzConnect: setDeactiveState invoked Dec 17 00:07:18 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:18 pioneer-sx-950 systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 17 00:07:18 pioneer-sx-950 sudo[4290]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: MPD Permissions set Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: QobuzConnect: setDeactiveState invoked Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: TidalConnect service stoped! Dec 17 00:07:19 pioneer-sx-950 systemd[1]: mpd.service: Deactivated successfully. Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 17 00:07:19 pioneer-sx-950 systemd[1]: mpd.service: Consumed 1.114s CPU time. Dec 17 00:07:19 pioneer-sx-950 systemd[1]: mpd.socket: Deactivated successfully. Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: Shairport-Sync Started Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 17 00:07:19 pioneer-sx-950 sudo[4343]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 17 00:07:19 pioneer-sx-950 sudo[4343]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: Executing endpoint qc_getconfig Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.175 [4335.4335] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.188 [4335.4335] INFO VolumeManager: [0x310228]: Setting new playback volume: 75 Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.189 [4335.4335] INFO VolumeManager: [0x310228]: Setting new mute state: 0 Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.189 [4335.4335] INFO QobuzConnect: [0x310bf8]: Client initialized! Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.189 [4335.4335] INFO SampleApp: Starting Avahi advertising, name: Pioneer SX-950, service name: _qobuz-connect._tcp Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.234 [4335.4335] INFO LocalConfigManager: [0x30fb08]: Starting Local Configuration server Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.234 [4335.4335] INFO SampleApp: Starting Local configuration server Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.235 [4335.4335] INFO SampleApp: Connected to UNIX socket client 0x2fa818 Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Starting mpd.service - Music Player Daemon... Dec 17 00:07:19 pioneer-sx-950 sudo[4354]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 17 00:07:19 pioneer-sx-950 sudo[4354]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 00:07:19 pioneer-sx-950 sudo[4343]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.325 [4335.4335] INFO SampleApp: Playback volume changed: 75 Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:19 pioneer-sx-950 systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: Starting Shairport Sync Dec 17 00:07:19 pioneer-sx-950 sudo[4364]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 17 00:07:19 pioneer-sx-950 sudo[4364]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:19 pioneer-sx-950 sudo[4371]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 17 00:07:19 pioneer-sx-950 sudo[4371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:19 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:19.473 [4335.4335] INFO SampleApp: Stopping Local configuration server Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 17 00:07:19 pioneer-sx-950 sudo[4374]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Dec 17 00:07:19 pioneer-sx-950 sudo[4374]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 17 00:07:19 pioneer-sx-950 systemd[1]: shairport-sync.service: Deactivated successfully. Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 17 00:07:19 pioneer-sx-950 sudo[4359]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 17 00:07:19 pioneer-sx-950 sudo[4359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 17 00:07:19 pioneer-sx-950 sudo[4359]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 17 00:07:19 pioneer-sx-950 sudo[4371]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:19 pioneer-sx-950 systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Dec 17 00:07:19 pioneer-sx-950 volumio[1366]: info: Shairport-Sync Started Dec 17 00:07:19 pioneer-sx-950 sudo[4374]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: Executing endpoint tc_getconfig Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Dec 17 00:07:20 pioneer-sx-950 vtcs[4380]: STARTING TidalConnect services, version: 1.5.2.56 Dec 17 00:07:20 pioneer-sx-950 vtcs[4380]: STARTED TidalConnect services. Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: Executing endpoint tc_connect Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: Connecting to TidalConnect Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::servicePushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::pushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioPushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output update for this device Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CorePlayQueue::getTrack 0 Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: verbose: CURRENT POSITION 0 Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::syncState stateService stop Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::syncState currentStatus stop Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::pushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioPushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output update for this device Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: No code Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::pushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioPushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output update for this device Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::servicePushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::pushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioPushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output update for this device Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CorePlayQueue::getTrack 0 Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: verbose: CURRENT POSITION 0 Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::syncState stateService stop Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::syncState currentStatus stop Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::pushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioPushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output update for this device Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: No code Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreStateMachine::pushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioPushState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output update for this device Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: MRS: Pushing multiroomSync output Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.RG5zunBDuuVZmqaEuaj8GWI7P002.c58fb4b88f86da7cf1595319df2df740.state.status' Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.RG5zunBDuuVZmqaEuaj8GWI7P002.c58fb4b88f86da7cf1595319df2df740.state.status' Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.RG5zunBDuuVZmqaEuaj8GWI7P002.c58fb4b88f86da7cf1595319df2df740.state.status' Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.RG5zunBDuuVZmqaEuaj8GWI7P002.c58fb4b88f86da7cf1595319df2df740.state.status' Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: Executing endpoint metavolumio Dec 17 00:07:20 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4335]: 20251217 00:07:21.242 [4335.4335] INFO SampleApp: shat down connection on UNIX socket Dec 17 00:07:21 pioneer-sx-950 volumio[1366]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Dec 17 00:07:21 pioneer-sx-950 volumio[1366]: info: QobuzConnect: setDeactiveState invoked Dec 17 00:07:21 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:21 pioneer-sx-950 systemd[1]: qobuz-connect.service: Deactivated successfully. Dec 17 00:07:21 pioneer-sx-950 systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Dec 17 00:07:21 pioneer-sx-950 systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 17 00:07:21 pioneer-sx-950 sudo[4364]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:21 pioneer-sx-950 volumio[1366]: info: Executing endpoint qc_getconfig Dec 17 00:07:21 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4424]: 20251217 00:07:21.490 [4424.4424] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 17 00:07:21 pioneer-sx-950 volumio[1366]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 17 00:07:21 pioneer-sx-950 volumio[1366]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4424]: 20251217 00:07:21.501 [4424.4424] INFO VolumeManager: [0x1991228]: Setting new playback volume: 75 Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4424]: 20251217 00:07:21.501 [4424.4424] INFO VolumeManager: [0x1991228]: Setting new mute state: 0 Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4424]: 20251217 00:07:21.501 [4424.4424] INFO QobuzConnect: [0x1991bf8]: Client initialized! Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4424]: 20251217 00:07:21.501 [4424.4424] INFO SampleApp: Starting Avahi advertising, name: Pioneer SX-950, service name: _qobuz-connect._tcp Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4424]: 20251217 00:07:21.529 [4424.4424] INFO LocalConfigManager: [0x1990b08]: Starting Local Configuration server Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4424]: 20251217 00:07:21.529 [4424.4424] INFO SampleApp: Starting Local configuration server Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4424]: 20251217 00:07:21.530 [4424.4424] INFO SampleApp: Connected to UNIX socket client 0x197b818 Dec 17 00:07:21 pioneer-sx-950 qobuz-connect[4424]: 20251217 00:07:21.640 [4424.4424] INFO SampleApp: Playback volume changed: 75 Dec 17 00:07:21 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:07:22 pioneer-sx-950 volumio[1366]: info: Executing endpoint metavolumio Dec 17 00:07:22 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 17 00:07:22 pioneer-sx-950 volumio[1366]: info: TidalConnect service started! Dec 17 00:07:22 pioneer-sx-950 mpd[4377]: 2025-12-17T00:07:22 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 17 00:07:22 pioneer-sx-950 systemd[1]: Started mpd.service - Music Player Daemon. Dec 17 00:07:22 pioneer-sx-950 sudo[4258]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:22 pioneer-sx-950 sudo[4327]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:22 pioneer-sx-950 volumio[1366]: error: MPD error: The expression evaluated to a falsy value: Dec 17 00:07:22 pioneer-sx-950 volumio[1366]: assert.ok(self.idling) Dec 17 00:07:22 pioneer-sx-950 volumio[1366]: error: The expression evaluated to a falsy value: Dec 17 00:07:22 pioneer-sx-950 volumio[1366]: assert.ok(self.idling) Dec 17 00:07:22 pioneer-sx-950 volumio[1366]: error: updateQueue error: null Dec 17 00:07:22 pioneer-sx-950 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 17 00:07:22 pioneer-sx-950 sudo[4354]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:22 pioneer-sx-950 volumio[1366]: info: Successfully started MPD Monitor Dec 17 00:07:22 pioneer-sx-950 mpd_monitor.sh[4432]: MPD Monitor Service: Starting MPD Monitor Service Dec 17 00:07:25 pioneer-sx-950 sudo[4437]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 17 00:07:25 pioneer-sx-950 sudo[4437]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:25 pioneer-sx-950 sudo[4439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 17 00:07:25 pioneer-sx-950 sudo[4439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:07:25 pioneer-sx-950 systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 17 00:07:25 pioneer-sx-950 systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 17 00:07:25 pioneer-sx-950 systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 17 00:07:26 pioneer-sx-950 systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 17 00:07:26 pioneer-sx-950 sudo[4437]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:26 pioneer-sx-950 sudo[4439]: pam_unix(sudo:session): session closed for user root Dec 17 00:07:26 pioneer-sx-950 mpd_monitor.sh[4442]: MPD Monitor Service: Starting MPD Monitor Service Dec 17 00:07:26 pioneer-sx-950 volumio[1366]: info: Successfully started MPD Monitor Dec 17 00:07:26 pioneer-sx-950 volumio[1366]: info: Successfully started MPD Monitor Dec 17 00:07:26 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 17 00:07:27 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 17 00:08:02 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 17 00:08:02 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 17 00:08:13 pioneer-sx-950 volumio[1366]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf Dec 17 00:08:15 pioneer-sx-950 volumio[1366]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf Dec 17 00:08:15 pioneer-sx-950 volumio[1366]: info: Folder /tmp/plugins removed Dec 17 00:08:17 pioneer-sx-950 volumio[1366]: info: Check plugin dependencies Dec 17 00:08:17 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 17 00:08:17 pioneer-sx-950 volumio[1366]: info: Checking if plugin already exists Dec 17 00:08:17 pioneer-sx-950 volumio[1366]: info: Rename folder Dec 17 00:08:17 pioneer-sx-950 volumio[1366]: info: Folder /tmp/downloaded_plugin.zip removed Dec 17 00:08:17 pioneer-sx-950 volumio[1366]: info: Move to category Dec 17 00:08:18 pioneer-sx-950 volumio[1366]: info: Checking if install.sh is present Dec 17 00:08:18 pioneer-sx-950 volumio[1366]: info: Executing install.sh Dec 17 00:08:18 pioneer-sx-950 sudo[4545]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/music_service/spop/install.sh Dec 17 00:08:18 pioneer-sx-950 sudo[4545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:08:18 pioneer-sx-950 volumio[1366]: info: Installing Go-librespot Dec 17 00:08:18 pioneer-sx-950 volumio[1366]: info: Checking old vollibrespot installs Dec 17 00:08:18 pioneer-sx-950 systemd[1]: Reloading. Dec 17 00:08:20 pioneer-sx-950 systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 17 00:08:20 pioneer-sx-950 systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 17 00:08:20 pioneer-sx-950 volumio[1366]: info: Downloading daemon Dec 17 00:08:22 pioneer-sx-950 volumio[1366]: info: Creating directories Dec 17 00:08:22 pioneer-sx-950 volumio[1366]: info: Creating data directory Dec 17 00:08:22 pioneer-sx-950 volumio[1366]: info: Creating Start Script Dec 17 00:08:22 pioneer-sx-950 systemd[1]: Reloading. Dec 17 00:08:24 pioneer-sx-950 systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 17 00:08:24 pioneer-sx-950 systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 17 00:08:24 pioneer-sx-950 sudo[4545]: pam_unix(sudo:session): session closed for user root Dec 17 00:08:24 pioneer-sx-950 volumio[1366]: Plugin install end detected on script Dec 17 00:08:24 pioneer-sx-950 volumio[1366]: info: Install script completed Dec 17 00:08:24 pioneer-sx-950 volumio[1366]: info: Adding reference to registry Dec 17 00:08:24 pioneer-sx-950 volumio[1366]: info: Done installing plugin. Dec 17 00:08:24 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 17 00:08:24 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 17 00:08:24 pioneer-sx-950 volumio[1366]: info: Folder /tmp/plugins removed Dec 17 00:08:24 pioneer-sx-950 volumio[1366]: info: Folder /tmp/downloaded_plugin.zip removed Dec 17 00:08:24 pioneer-sx-950 volumio[1366]: info: Folder /data/temp removed Dec 17 00:08:26 pioneer-sx-950 volumio[1366]: info: Enabling plugin spop Dec 17 00:08:26 pioneer-sx-950 volumio[1366]: info: Loading plugin "spop"... Dec 17 00:08:27 pioneer-sx-950 volumio[1366]: info: PLUGIN START: spop Dec 17 00:08:28 pioneer-sx-950 volumio[1366]: info: Creating Spotify config file Dec 17 00:08:28 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 00:08:28 pioneer-sx-950 volumio[1366]: info: Done. Dec 17 00:08:28 pioneer-sx-950 volumio[1366]: info: Spotify config file written Dec 17 00:08:28 pioneer-sx-950 volumio[1366]: info: No need to fix Spotify hosts Dec 17 00:08:28 pioneer-sx-950 sudo[4619]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 17 00:08:28 pioneer-sx-950 sudo[4619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 00:08:28 pioneer-sx-950 systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 17 00:08:28 pioneer-sx-950 systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 17 00:08:28 pioneer-sx-950 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 17 00:08:28 pioneer-sx-950 go-librespot[4621]: go-librespot daemon starting... Dec 17 00:08:28 pioneer-sx-950 sudo[4619]: pam_unix(sudo:session): session closed for user root Dec 17 00:08:28 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:28+01:00" level=info msg="running go-librespot 0.4.0" Dec 17 00:08:28 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:28+01:00" level=debug msg="no app state found" Dec 17 00:08:28 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:28+01:00" level=debug msg="stored credentials not found" Dec 17 00:08:28 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:28+01:00" level=info msg="generated new device id: def0ef6f32e11680187d2f0725ee9de407d5ec27" Dec 17 00:08:28 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:28+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 17 00:08:28 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 17 00:08:28 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:28+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 17 00:08:28 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:28+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 17 00:08:28 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:28+01:00" level=info msg="zeroconf server listening on port 44083" Dec 17 00:08:31 pioneer-sx-950 volumio[1366]: info: go-librespot daemon successfully initialized Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="obtained new client token: AACZ+X1FeoQz86pcsHqYyUeD3vsldOnCJKXlJKUa7c4jss+FhE+Db9VTxeCr7R44sqTzClZfdhEW2DY9E5yvc0BQiyhS0ecNYHueoqmWgXCfJtWHE+i37wNq6cD/B9TZOv1sMjZSoL7Za5P8WGdtrpdsh4CksiGai+FUUGCqxaB21hfGipDVrs7B+P/UH774k4cTARfaXDf6wYh9CItVX8n5hDlVipuZz5/ypje7uvtBaZOz7cAnnXG87Q==" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="completed keyexchange" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="completed challenge" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=info msg="authenticated AP" username="oh***93" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=info msg="authenticated Login5" username="oh***93" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=info msg="accepted zeroconf from DAGROS" username="oh***93" Dec 17 00:08:33 pioneer-sx-950 nmbd[2486]: [2025/12/17 00:08:33.907335, 0] ../../source3/nmbd/nmbd_namequery.c:109(query_name_response) Dec 17 00:08:33 pioneer-sx-950 nmbd[2486]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.33 for name WORKGROUP<1d>. Dec 17 00:08:33 pioneer-sx-950 nmbd[2486]: This response was from IP 192.168.1.8, reporting an IP address of 192.168.1.8. Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="dealer connection opened" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=trace msg="starting accesspoint recv loop" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=trace msg="starting dealer recv loop" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=trace msg="received accesspoint ping" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=debug msg="received connection id: NzRlODFiMzAtZjAx...QUY0MTE5NzhEQQ==" Dec 17 00:08:33 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:33+01:00" level=trace msg="received accesspoint pong ack" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="handling transfer player command from 9491ddd80d4b9fcd9bad2ac66b842a21bd8d5527" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:355M8b6ckmpD7zNbmmIPTN" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=trace msg="fetched new page 0 with 34 items (list: 34)" uri="spotify:playlist:355M8b6ckmpD7zNbmmIPTN" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="loading track (paused: true, position: 67105ms)" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:34 pioneer-sx-950 volumio[1366]: info: Initializing connection to go-librespot Websocket Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="new websocket client" Dec 17 00:08:34 pioneer-sx-950 volumio[1366]: info: Connection to go-librespot Websocket established Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=trace msg="emitting websocket event: will_play" Dec 17 00:08:34 pioneer-sx-950 volumio[1366]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:355M8b6ckmpD7zNbmmIPTN","uri":"spotify:track:59EKMmwwDJxtEw6EjMVeaT","play_origin":"playlist/ondemand"}} Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3527" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="selected format OGG_VORBIS_320 (ac02a1c3a4e86837e73da7bc1d8f8f383f3dc02b)" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="requested aes key for file ac02a1c3a4e86837e73da7bc1d8f8f383f3dc02b, gid: 59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="fetched first chunk of 12, total size is 6049696 bytes" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2211" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="fetched chunk 6/11, size: 524288" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="fetched chunk 8/11, size: 524288" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:34 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:34+01:00" level=debug msg="fetched chunk 7/11, size: 524288" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=debug msg="fetched chunk 5/11, size: 524288" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=trace msg="seek to 67105ms (diff: 94ms, samples: 2959330, bytes: 2737698)" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=debug msg="created new output device" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=info msg="loaded track \"Gary\" (paused: true, position: 67105ms, duration: 150005ms, prefetched: false)" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=trace msg="emitting websocket event: metadata" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=trace msg="emitting websocket event: active" Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:59EKMmwwDJxtEw6EjMVeaT","name":"Gary","artist_names":["Blossoms"],"album_name":"Gary","album_cover_url":"https://i.scdn.co/image/ab67616d00001e028148cc95f85695e2399ebb33","position":67105,"duration":150005,"release_date":"year:2024 month:9 day:20","track_number":3,"disc_number":1}} Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: SPOTIFY: received: {"type":"active","data":null} Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: info: Aligning Spotify Volume to Volumio Volume Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: info: CoreCommandRouter::volumioGetState Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: info: Setting Spotify Volume from Volumio: 46 Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=debug msg="sending successful reply for dealer request" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:59EKMmwwDJxtEw6EjMVeaT" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 00:08:35 pioneer-sx-950 go-librespot[4622]: time="2025-12-17T00:08:35+01:00" level=trace msg="emitting websocket event: paused" Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:355M8b6ckmpD7zNbmmIPTN","uri":"spotify:track:59EKMmwwDJxtEw6EjMVeaT","play_origin":"playlist/ondemand"}} Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: TypeError: Cannot read properties of undefined (reading 'service') Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at WebSocket.emit (node:events:514:28) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at Receiver.emit (node:events:514:28) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at writeOrBuffer (node:internal/streams/writable:399:12) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at _write (node:internal/streams/writable:340:10) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at Writable.write (node:internal/streams/writable:344:10) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at Socket.emit (node:events:514:28) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: at addChunk (node:internal/streams/readable:343:12) Dec 17 00:08:35 pioneer-sx-950 volumio[1366]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 17 00:08:36 pioneer-sx-950 sudo[4659]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-17 00:07' Dec 17 00:08:36 pioneer-sx-950 sudo[4659]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"