Mar 26 16:22:00 cocobox volumio[1476]: info: Successfully Updated MyVolumio device Mar 26 16:22:00 cocobox volumio[1476]: info: Successfully Updated MyVolumio device Mar 26 16:22:01 cocobox volumio[1476]: info: TidalConnect service stoped! Mar 26 16:22:01 cocobox volumio[1476]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Mar 26 16:22:01 cocobox volumio[1476]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Mar 26 16:22:01 cocobox sudo[2464]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Mar 26 16:22:01 cocobox sudo[2464]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 16:22:01 cocobox systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Mar 26 16:22:01 cocobox sudo[2464]: pam_unix(sudo:session): session closed for user root Mar 26 16:22:01 cocobox volumio[1476]: info: Executing endpoint tc_getconfig Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Mar 26 16:22:01 cocobox vtcs[2467]: STARTING TidalConnect services, version: 1.6.1 Mar 26 16:22:01 cocobox vtcs[2467]: STARTED TidalConnect services. Mar 26 16:22:01 cocobox volumio[1476]: info: Executing endpoint tc_connect Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Mar 26 16:22:01 cocobox volumio[1476]: info: Connecting to TidalConnect Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::servicePushState Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::pushState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioPushState Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: 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} Mar 26 16:22:01 cocobox volumio[1476]: verbose: CURRENT POSITION 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::syncState stateService stop Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::syncState currentStatus stop Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::pushState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioPushState Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: No code Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::pushState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioPushState Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::servicePushState Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::pushState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioPushState Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: 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} Mar 26 16:22:01 cocobox volumio[1476]: verbose: CURRENT POSITION 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::syncState stateService stop Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::syncState currentStatus stop Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::pushState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioPushState Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: No code Mar 26 16:22:01 cocobox volumio[1476]: info: CoreStateMachine::pushState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioPushState Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:22:01 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output Mar 26 16:22:01 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:01 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:02 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:02 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:02 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 26 16:22:02 cocobox volumio[1476]: info: CoreCommandRouter::volumioPlay Mar 26 16:22:02 cocobox volumio[1476]: info: CoreStateMachine::play index undefined Mar 26 16:22:02 cocobox volumio[1476]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 26 16:22:02 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:03 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:03 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:03 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 26 16:22:03 cocobox volumio[1476]: info: CoreCommandRouter::volumioPlay Mar 26 16:22:03 cocobox volumio[1476]: info: CoreStateMachine::play index undefined Mar 26 16:22:03 cocobox volumio[1476]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 26 16:22:03 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:04 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::volumioPlay Mar 26 16:22:04 cocobox volumio[1476]: info: CoreStateMachine::play index undefined Mar 26 16:22:04 cocobox volumio[1476]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 26 16:22:04 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:04 cocobox volumio[1476]: info: TidalConnect service started! Mar 26 16:22:04 cocobox volumio[1476]: [Metrics] CommandRouter: 27s 159.19ms Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::volumiosetStartupVolume Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 16:22:04 cocobox volumio[1476]: info: VolumeController:: Setting startup Volume 10 Mar 26 16:22:04 cocobox volumio[1476]: info: VolumeController::SetAlsaVolume10 Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::Close All Modals sent Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::Close All Modals sent Mar 26 16:22:04 cocobox volumio[1476]: info: CoreStateMachine::pushState Mar 26 16:22:04 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::volumioPushState Mar 26 16:22:04 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:22:04 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output Mar 26 16:22:04 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:04 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 26 16:22:05 cocobox volumio[1476]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 26 16:22:05 cocobox volumio[1476]: info: Received Get System Version Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 26 16:22:05 cocobox volumio[1476]: info: Received Get System Info Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 16:22:05 cocobox volumio[1476]: info: Discovery: Getting this device information Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:05 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 26 16:22:05 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Mar 26 16:22:06 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 26 16:22:06 cocobox volumio[1476]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Mar 26 16:22:06 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:06 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:10 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 26 16:22:10 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 26 16:22:10 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 26 16:22:10 cocobox volumio-remote-updater[1106]: Test mode disabled Mar 26 16:22:10 cocobox volumio-remote-updater[1106]: Alpha mode disabled Mar 26 16:22:10 cocobox volumio-remote-updater[1106]: Alpha legacy test mode disabled Mar 26 16:22:10 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Mar 26 16:22:10 cocobox volumio[1476]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Mar 26 16:22:10 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Mar 26 16:22:10 cocobox upmpdcli[2506]: writing RSA key Mar 26 16:22:11 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 16:22:11 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 16:22:11 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Mar 26 16:22:11 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Mar 26 16:22:11 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Mar 26 16:22:11 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Mar 26 16:22:11 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetBrowseSources Mar 26 16:22:11 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 26 16:22:11 cocobox volumio[1476]: info: BOOT COMPLETED Mar 26 16:22:14 cocobox systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Mar 26 16:22:19 cocobox systemd[1]: setdatetime-helper.service: Deactivated successfully. Mar 26 16:22:19 cocobox systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Mar 26 16:22:21 cocobox volumio[1476]: info: VolumeController::SetAlsaVolume56 Mar 26 16:22:21 cocobox volumio[1476]: info: CoreStateMachine::pushState Mar 26 16:22:21 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:21 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 26 16:22:21 cocobox volumio[1476]: info: CoreCommandRouter::volumioPushState Mar 26 16:22:21 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:22:21 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output Mar 26 16:22:21 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:21 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:23 cocobox volumio[1476]: info: VolumeController::SetAlsaVolume75 Mar 26 16:22:23 cocobox volumio[1476]: info: CoreStateMachine::pushState Mar 26 16:22:23 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:23 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 26 16:22:23 cocobox volumio[1476]: info: CoreCommandRouter::volumioPushState Mar 26 16:22:23 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output update for this device Mar 26 16:22:23 cocobox volumio[1476]: info: MRS: Pushing multiroomSync output Mar 26 16:22:23 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:23 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:26 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: multiroom , enableAudioOutput Mar 26 16:22:26 cocobox volumio[1476]: info: MRS: Starting browser stream Mar 26 16:22:26 cocobox volumio[1476]: info: MRS: Setting this device as Streaming Server Mar 26 16:22:26 cocobox volumio[1476]: info: Mar 26 16:22:26 cocobox volumio[1476]: [1774538546520] ---------------------------- MRS: Setting Streaming Server Mar 26 16:22:26 cocobox volumio[1476]: info: Enabled audio output: browserPlayback Mar 26 16:22:26 cocobox volumio[1476]: info: MRS: enable multiroom server output Mar 26 16:22:26 cocobox volumio[1476]: info: MRS: Set multiroom target PCM to volumioMultiRoom Mar 26 16:22:26 cocobox volumio[1476]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioMultiRoom Mar 26 16:22:26 cocobox volumio[1476]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Mar 26 16:22:26 cocobox volumio[1476]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioLocalPlayback Mar 26 16:22:26 cocobox volumio[1476]: info: MRS: STARTING volumioStreaming Mar 26 16:22:26 cocobox sudo[2563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Mar 26 16:22:26 cocobox sudo[2563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 16:22:26 cocobox sudo[2563]: pam_unix(sudo:session): session closed for user root Mar 26 16:22:26 cocobox sudo[2565]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Mar 26 16:22:26 cocobox sudo[2565]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 16:22:26 cocobox systemd[1]: Started volumioStreaming.service - VolumioStreamingService. Mar 26 16:22:26 cocobox sudo[2565]: pam_unix(sudo:session): session closed for user root Mar 26 16:22:26 cocobox volumio[1476]: info: MRS: volumioStreaming STARTED Mar 26 16:22:26 cocobox sudo[2570]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Mar 26 16:22:26 cocobox sudo[2570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 16:22:26 cocobox sudo[2570]: pam_unix(sudo:session): session closed for user root Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 16:22:37 cocobox volumio[1476]: info: Retrieving Cloud Streaming UI Mar 26 16:22:37 cocobox volumio[1476]: info: Getting Tidal Cloud Configuration Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 16:22:37 cocobox volumio[1476]: info: Getting Qobuz Cloud Configuration Mar 26 16:22:37 cocobox volumio[1476]: info: Asking plugin for UI Config Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 16:22:37 cocobox volumio[1476]: info: Getting Spotify Cloud Configuration Mar 26 16:22:37 cocobox volumio[1476]: info: Asking plugin for UI Config Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 16:22:37 cocobox volumio[1476]: info: Saving Spotify Acccount Mar 26 16:22:37 cocobox volumio[1476]: info: Got it Mar 26 16:22:37 cocobox volumio[1476]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Mar 26 16:22:37 cocobox volumio[1476]: info: Got it Mar 26 16:22:37 cocobox volumio[1476]: info: Got Tidal Cloud Configuration Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetBrowseSources Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetBrowseSources Mar 26 16:22:37 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetBrowseSources Mar 26 16:22:38 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Mar 26 16:22:38 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Mar 26 16:22:38 cocobox wpa_supplicant[1436]: RRM: Ignoring radio measurement request: Not RRM network Mar 26 16:22:40 cocobox wpa_supplicant[1436]: RRM: Ignoring radio measurement request: Not RRM network Mar 26 16:22:42 cocobox wpa_supplicant[1436]: RRM: Ignoring radio measurement request: Not RRM network Mar 26 16:22:43 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetQueue Mar 26 16:22:43 cocobox volumio[1476]: info: CoreStateMachine::getQueue Mar 26 16:22:43 cocobox volumio[1476]: info: CorePlayQueue::getQueue Mar 26 16:22:44 cocobox wpa_supplicant[1436]: RRM: Ignoring radio measurement request: Not RRM network Mar 26 16:22:44 cocobox wpa_supplicant[1436]: wlan0: WNM: Preferred List Available Mar 26 16:22:45 cocobox wpa_supplicant[1436]: wlan0: Trying to associate with 0a:b6:57:40:46:90 (SSID='Prometheus' freq=5500 MHz) Mar 26 16:22:45 cocobox kernel: ieee80211 phy0: brcmf_p2p_send_action_frame: Unknown Frame: category 0xa, action 0x8 Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: carrier lost - roaming Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: changing route to 192.168.0.0/24 Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: changing default route via 192.168.0.1 Mar 26 16:22:45 cocobox wpa_supplicant[1436]: wlan0: Associated with 0a:b6:57:40:46:90 Mar 26 16:22:45 cocobox wpa_supplicant[1436]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Mar 26 16:22:45 cocobox wpa_supplicant[1436]: wlan0: WPA: Key negotiation completed with 0a:b6:57:40:46:90 [PTK=CCMP GTK=CCMP] Mar 26 16:22:45 cocobox wpa_supplicant[1436]: wlan0: CTRL-EVENT-CONNECTED - Connection to 0a:b6:57:40:46:90 completed [id=0 id_str=] Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: carrier acquired Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: IAID 67:6a:47:24 Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: soliciting an IPv6 router Mar 26 16:22:45 cocobox volumio[1476]: info: Received Get System Info Mar 26 16:22:45 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 16:22:45 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 16:22:45 cocobox volumio[1476]: info: Discovery: Getting this device information Mar 26 16:22:45 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:45 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:45 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 16:22:45 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 26 16:22:45 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: rebinding lease of 192.168.0.157 Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: leased 192.168.0.157 for 864000 seconds Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: changing route to 192.168.0.0/24 Mar 26 16:22:45 cocobox dhcpcd[1117]: wlan0: changing default route via 192.168.0.1 Mar 26 16:22:45 cocobox systemd[1]: Stopped target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 26 16:22:45 cocobox systemd[1]: Stopping ip-changed@wlan0.target - IP Address changed on wlan0... Mar 26 16:22:45 cocobox systemd[1]: welcome.service: Deactivated successfully. Mar 26 16:22:45 cocobox systemd[1]: Stopped welcome.service - Show a welcome message on console. Mar 26 16:22:45 cocobox systemd[1]: Stopping welcome.service - Show a welcome message on console... Mar 26 16:22:45 cocobox systemd[1]: Starting welcome.service - Show a welcome message on console... Mar 26 16:22:45 cocobox welcome[2657]: Resolved ip:[1] 192.168.0.157 Mar 26 16:22:45 cocobox systemd[1]: Finished welcome.service - Show a welcome message on console. Mar 26 16:22:45 cocobox systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 26 16:22:46 cocobox volumio[1476]: info: Received Get System Info Mar 26 16:22:46 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 16:22:46 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 16:22:46 cocobox volumio[1476]: info: Discovery: Getting this device information Mar 26 16:22:46 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:46 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:46 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 16:22:46 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 26 16:22:46 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 26 16:22:46 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 26 16:22:46 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 26 16:22:47 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 26 16:22:47 cocobox volumio[1476]: info: Received Get System Info Mar 26 16:22:47 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 26 16:22:47 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 26 16:22:47 cocobox volumio[1476]: info: Discovery: Getting this device information Mar 26 16:22:47 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:22:47 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:22:47 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 26 16:22:47 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:22:47.472+01:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 26 16:22:51 cocobox wpa_supplicant[1436]: RRM: Ignoring radio measurement request: Not RRM network Mar 26 16:22:53 cocobox wpa_supplicant[1436]: RRM: Ignoring radio measurement request: Not RRM network Mar 26 16:22:56 cocobox wpa_supplicant[1436]: RRM: Ignoring radio measurement request: Not RRM network Mar 26 16:22:58 cocobox wpa_supplicant[1436]: RRM: Ignoring radio measurement request: Not RRM network Mar 26 16:23:37 cocobox volumio[1476]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf Mar 26 16:23:37 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:37.104+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:38 cocobox volumio[1476]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf Mar 26 16:23:38 cocobox volumio[1476]: info: Folder /tmp/plugins removed Mar 26 16:23:38 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:38.332+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:38 cocobox volumio[1476]: info: Check plugin dependencies Mar 26 16:23:38 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:38.597+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:38 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 26 16:23:38 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:38.626+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:38 cocobox volumio[1476]: info: Checking if plugin already exists Mar 26 16:23:38 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:38.630+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:38 cocobox volumio[1476]: info: Rename folder Mar 26 16:23:38 cocobox volumio[1476]: info: Folder /tmp/downloaded_plugin.zip removed Mar 26 16:23:38 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:38.643+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:38 cocobox volumio[1476]: info: Move to category Mar 26 16:23:39 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:39.963+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:39 cocobox volumio[1476]: info: Checking if install.sh is present Mar 26 16:23:39 cocobox volumio[1476]: info: Executing install.sh Mar 26 16:23:40 cocobox sudo[2766]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/music_service/spop/install.sh Mar 26 16:23:40 cocobox sudo[2766]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 16:23:40 cocobox volumio[1476]: info: Installing Go-librespot Mar 26 16:23:40 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:40.012+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:40 cocobox volumio[1476]: info: Checking old vollibrespot installs Mar 26 16:23:40 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:40.026+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:40 cocobox systemd[1]: Reloading. Mar 26 16:23:40 cocobox 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. Mar 26 16:23:40 cocobox 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. Mar 26 16:23:40 cocobox volumio[1476]: info: Downloading daemon Mar 26 16:23:40 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:40.620+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:41 cocobox volumio[1476]: info: Creating directories Mar 26 16:23:41 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:41.784+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:41 cocobox volumio[1476]: info: Creating data directory Mar 26 16:23:41 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:41.795+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:41 cocobox volumio[1476]: info: Creating Start Script Mar 26 16:23:41 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:41.801+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:41 cocobox systemd[1]: Reloading. Mar 26 16:23:42 cocobox 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. Mar 26 16:23:42 cocobox 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. Mar 26 16:23:42 cocobox volumio[1476]: Plugin install end detected on script Mar 26 16:23:42 cocobox sudo[2766]: pam_unix(sudo:session): session closed for user root Mar 26 16:23:42 cocobox volumio[1476]: info: Install script completed Mar 26 16:23:42 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:42.319+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:42 cocobox volumio[1476]: info: Adding reference to registry Mar 26 16:23:42 cocobox volumio5-onboarding[1789]: time=2026-03-26T16:23:42.328+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 26 16:23:42 cocobox volumio[1476]: info: Done installing plugin. Mar 26 16:23:42 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 26 16:23:42 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 26 16:23:42 cocobox volumio[1476]: info: Folder /tmp/plugins removed Mar 26 16:23:42 cocobox volumio[1476]: info: Folder /tmp/downloaded_plugin.zip removed Mar 26 16:23:42 cocobox volumio[1476]: info: Folder /data/temp removed Mar 26 16:23:44 cocobox volumio[1476]: info: Enabling plugin spop Mar 26 16:23:44 cocobox volumio[1476]: info: Loading plugin "spop"... Mar 26 16:23:45 cocobox volumio[1476]: info: PLUGIN START: spop Mar 26 16:23:45 cocobox volumio[1476]: info: Creating Spotify config file Mar 26 16:23:45 cocobox volumio[1476]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 16:23:45 cocobox volumio[1476]: info: Done. Mar 26 16:23:45 cocobox volumio[1476]: info: Spotify config file written Mar 26 16:23:45 cocobox volumio[1476]: info: No need to fix Spotify hosts Mar 26 16:23:45 cocobox sudo[2824]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 16:23:45 cocobox sudo[2824]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 16:23:45 cocobox 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. Mar 26 16:23:45 cocobox 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. Mar 26 16:23:45 cocobox systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 26 16:23:45 cocobox go-librespot[2826]: go-librespot daemon starting... Mar 26 16:23:45 cocobox sudo[2824]: pam_unix(sudo:session): session closed for user root Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+01:00" level=info msg="running go-librespot 0.7.1" Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+01:00" level=debug msg="no app state found" Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+01:00" level=debug msg="stored credentials not found" Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+01:00" level=info msg="generated new device id: 7a00a54cadc7528c9ab01a3716ea0e542ebdaa76" Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+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-gae2.spotify.com:80]" Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+01:00" level=info msg="zeroconf server listening on port 35713" Mar 26 16:23:45 cocobox go-librespot[2827]: time="2026-03-26T16:23:45+01:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Mar 26 16:23:48 cocobox volumio[1476]: info: go-librespot daemon successfully initialized Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="obtained new client token: AAAKbIrKmbYKtUN0e8xCuYDm3M/I0P+f8u0q0oke5TKPtGlFOkpIdt8JGBDKKyUD3Zsu8QEo05+WnRqoigHUSJ76TKPUmVUHRrqGvCBmPIhPPfcrso40wiOf5YfHGoRQUC8Up5ql48FrUyhDe0d7G9+t2UxDzyZqipoCgehIzZrDn4lWt88WcN/XnAXXjyC3JxrNAyzWOT6Vl7Va4mzBxBBdsVr/s+WzpOQIricFlfdzIRWdW1n2hFze2A==" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="completed keyexchange" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="completed challenge" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=info msg="authenticated AP" username="31************************l4" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=info msg="authenticated Login5" username="31************************l4" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=info msg="accepted zeroconf from CyberTron Phone" username="31************************l4" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="dealer connection opened" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=trace msg="starting accesspoint recv loop" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=trace msg="starting dealer recv loop" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=trace msg="received accesspoint ping" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=debug msg="received connection id: YmU3NTdjNTItM2Rk...NUNDOTlBRTE0Qg==" Mar 26 16:23:50 cocobox go-librespot[2827]: time="2026-03-26T16:23:50+01:00" level=trace msg="received accesspoint pong ack" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 26 16:23:51 cocobox volumio[1476]: info: Initializing connection to go-librespot Websocket Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="new websocket client" Mar 26 16:23:51 cocobox volumio[1476]: info: Connection to go-librespot Websocket established Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="handling transfer player command from 4360198c1acc8a5ac5c5798adcc51298c3bc0750" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="resolved context of track" uri="spotify:user:31fxuh4572xqauf2gmik67hiphl4:collection" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=trace msg="fetched new page 0 with 464 items (list: 464)" uri="spotify:user:31fxuh4572xqauf2gmik67hiphl4:collection" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="loading track (paused: true, position: 399769ms)" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=trace msg="emitting websocket event: will_play" Mar 26 16:23:51 cocobox volumio[1476]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:user:31fxuh4572xqauf2gmik67hiphl4:collection","uri":"spotify:track:6mXLhrK5R19RujCB9Dk0zO","play_origin":"playlist"}} Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="selected format OGG_VORBIS_320 (78dd87e396a2a399b1241bcb26c225cf2dad92fb)" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="requested aes key for file 78dd87e396a2a399b1241bcb26c225cf2dad92fb, gid: 6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1722" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:51 cocobox go-librespot[2827]: time="2026-03-26T16:23:51+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1314" Mar 26 16:23:52 cocobox volumio[1476]: info: Tunnel connection is inactive, restarting it Mar 26 16:23:52 cocobox volumio[1476]: info: Starting Tunnel 1 Mar 26 16:23:52 cocobox volumio[1476]: info: Starting Tunnel Connection Checker Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="fetched first chunk of 37, total size is 19148288 bytes" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:53 cocobox sudo[2859]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Mar 26 16:23:53 cocobox sudo[2859]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 26 16:23:53 cocobox autossh[2443]: received signal to exit (15) Mar 26 16:23:53 cocobox systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Mar 26 16:23:53 cocobox systemd[1]: sshtunnel.service: Deactivated successfully. Mar 26 16:23:53 cocobox systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Mar 26 16:23:53 cocobox wpa_supplicant[1436]: RRM: Ignoring radio measurement request: Not RRM network Mar 26 16:23:53 cocobox systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Mar 26 16:23:53 cocobox sudo[2859]: pam_unix(sudo:session): session closed for user root Mar 26 16:23:53 cocobox volumio[1476]: info: Remote SSH Started Mar 26 16:23:53 cocobox autossh[2862]: port set to 0, monitoring disabled Mar 26 16:23:53 cocobox autossh[2862]: starting ssh (count 1) Mar 26 16:23:53 cocobox autossh[2862]: ssh child pid is 2865 Mar 26 16:23:53 cocobox volumio[1476]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Mar 26 16:23:53 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:23:53 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="fetched chunk 3/36, size: 524288" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:53 cocobox volumiossh-tunnel[2865]: Warning: Permanently added '[eu7.myvolumio.org]:2222' (RSA) to the list of known hosts. Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="fetched chunk 36/36, size: 273920" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="fetched chunk 2/36, size: 524288" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="fetched chunk 1/36, size: 524288" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="fetched chunk 35/36, size: 524288" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=trace msg="seek to 399769ms (diff: 119ms, samples: 17629812, bytes: 18661886)" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="created new output device" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=info msg="loaded track \"Nova\" (paused: true, position: 399769ms, duration: 412758ms, prefetched: false)" uri="spotify:track:6mXLhrK5R19RujCB9Dk0zO" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=trace msg="emitting websocket event: metadata" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=trace msg="emitting websocket event: active" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="sending successful reply for dealer request" Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 26 16:23:53 cocobox volumio[1476]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6mXLhrK5R19RujCB9Dk0zO","name":"Nova","artist_names":["2UP","Jaen Paniagua"],"album_name":"Nova","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a1538b3e8079dd13de792b09","position":399769,"duration":412758,"release_date":"year:2022 month:7 day:1","track_number":1,"disc_number":1}} Mar 26 16:23:53 cocobox volumio[1476]: SPOTIFY: received: {"type":"active","data":null} Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 26 16:23:53 cocobox go-librespot[2827]: time="2026-03-26T16:23:53+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 26 16:23:53 cocobox volumio[1476]: info: Aligning Spotify Volume to Volumio Volume Mar 26 16:23:53 cocobox volumio[1476]: info: CoreCommandRouter::volumioGetState Mar 26 16:23:53 cocobox volumio[1476]: info: CorePlayQueue::getTrack 0 Mar 26 16:23:53 cocobox volumio[1476]: info: Setting Spotify Volume from Volumio: 60 Mar 26 16:23:54 cocobox go-librespot[2827]: time="2026-03-26T16:23:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 16:23:54 cocobox go-librespot[2827]: time="2026-03-26T16:23:54+01:00" level=trace msg="emitting websocket event: paused" Mar 26 16:23:54 cocobox volumio[1476]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:user:31fxuh4572xqauf2gmik67hiphl4:collection","uri":"spotify:track:6mXLhrK5R19RujCB9Dk0zO","play_origin":"playlist"}} Mar 26 16:23:54 cocobox volumio[1476]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 26 16:23:54 cocobox volumio[1476]: TypeError: Cannot read properties of undefined (reading 'service') Mar 26 16:23:54 cocobox volumio[1476]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Mar 26 16:23:54 cocobox volumio[1476]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Mar 26 16:23:54 cocobox volumio[1476]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Mar 26 16:23:54 cocobox volumio[1476]: at WebSocket.emit (node:events:514:28) Mar 26 16:23:54 cocobox volumio[1476]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 26 16:23:54 cocobox volumio[1476]: at Receiver.emit (node:events:514:28) Mar 26 16:23:54 cocobox volumio[1476]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 26 16:23:54 cocobox volumio[1476]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 26 16:23:54 cocobox volumio[1476]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 26 16:23:54 cocobox volumio[1476]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 26 16:23:54 cocobox volumio[1476]: at writeOrBuffer (node:internal/streams/writable:399:12) Mar 26 16:23:54 cocobox volumio[1476]: at _write (node:internal/streams/writable:340:10) Mar 26 16:23:54 cocobox volumio[1476]: at Writable.write (node:internal/streams/writable:344:10) Mar 26 16:23:54 cocobox volumio[1476]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Mar 26 16:23:54 cocobox volumio[1476]: at Socket.emit (node:events:514:28) Mar 26 16:23:54 cocobox volumio[1476]: at addChunk (node:internal/streams/readable:343:12) Mar 26 16:23:54 cocobox volumio[1476]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 26 16:23:54 cocobox sudo[2880]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-26 16:22' Mar 26 16:23:54 cocobox sudo[2880]: 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="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"