May 29 08:21:00 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 29 08:21:00 volumio volumio[1245]: info: Received Get System Info May 29 08:21:00 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:21:00 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:21:00 volumio volumio[1245]: info: Discovery: Getting this device information May 29 08:21:00 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 29 08:21:00 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:00 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:21:00 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard May 29 08:21:01 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken May 29 08:21:01 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 29 08:21:01 volumio volumio[1245]: info: Received Get System Info May 29 08:21:01 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:21:01 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:21:01 volumio volumio[1245]: info: Discovery: Getting this device information May 29 08:21:01 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 29 08:21:01 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:01 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:21:01 volumio sudo[2025]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 29 08:21:01 volumio sudo[2025]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:21:01 volumio sudo[2025]: pam_unix(sudo:session): session closed for user root May 29 08:21:01 volumio sudo[2027]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 29 08:21:01 volumio sudo[2027]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:21:01 volumio sudo[2027]: pam_unix(sudo:session): session closed for user root May 29 08:21:01 volumio sudo[2030]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 29 08:21:01 volumio sudo[2030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:21:01 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. May 29 08:21:01 volumio sudo[2030]: pam_unix(sudo:session): session closed for user root May 29 08:21:01 volumio volumio[1245]: info: Upmpdcli Daemon Started May 29 08:21:01 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken May 29 08:21:02 volumio volumio[1245]: info: Initializing connection to go-librespot Websocket May 29 08:21:02 volumio go-librespot[1899]: time="2025-05-29T08:21:02+03:00" level=debug msg="new websocket client" May 29 08:21:02 volumio volumio[1245]: info: Connection to go-librespot Websocket established May 29 08:21:03 volumio volumio[1245]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 29 08:21:04 volumio volumio[1245]: Cannot compose Albumart path May 29 08:21:04 volumio volumio[1245]: Cannot compose Albumart path May 29 08:21:04 volumio volumio[1245]: Cannot compose Albumart path May 29 08:21:04 volumio volumio[1245]: Cannot compose Albumart path May 29 08:21:04 volumio volumio[1245]: Cannot compose Albumart path May 29 08:21:04 volumio volumio[1245]: Cannot compose Albumart path May 29 08:21:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:05 volumio upmpdcli[2050]: writing RSA key May 29 08:21:05 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:05 volumio volumio[1245]: info: Getting Spotify volume May 29 08:21:05 volumio volumio[1245]: info: Spotify volume: 100 May 29 08:21:05 volumio volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 May 29 08:21:05 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 29 08:21:05 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:05 volumio volumio[1245]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:21:05 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:06 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso May 29 08:21:06 volumio volumio[1245]: info: Adding plugin bluetooth to MyMusic Plugins May 29 08:21:06 volumio volumio[1245]: info: Adding plugin multiroom to MyMusic Plugins May 29 08:21:06 volumio volumio[1245]: info: Adding plugin metavolumio to MyMusic Plugins May 29 08:21:06 volumio volumio[1245]: info: Adding plugin cd_controller to MyMusic Plugins May 29 08:21:06 volumio volumio[1245]: info: Adding plugin smart_inputs to MyMusic Plugins May 29 08:21:06 volumio volumio[1245]: info: Adding plugin tidalconnect to MyMusic Plugins May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio May 29 08:21:06 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:06 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:06 volumio volumio[1245]: info: Starting MyVolumio Remote Streaming Endpoints May 29 08:21:06 volumio volumio[1245]: info: MyVolumio login type: Token May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started May 29 08:21:06 volumio volumio[1245]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... May 29 08:21:07 volumio volumio[1245]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded May 29 08:21:07 volumio volumio[1245]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services May 29 08:21:07 volumio volumio[1245]: info: Streaming services startup May 29 08:21:07 volumio volumio[1245]: info: Starting Streaming Daemon May 29 08:21:07 volumio volumio[1245]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started May 29 08:21:07 volumio sudo[2055]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 29 08:21:07 volumio sudo[2055]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:21:07 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:07 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:07 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 29 08:21:07 volumio sudo[2055]: pam_unix(sudo:session): session closed for user root May 29 08:21:07 volumio volumio[1245]: error: Cannot start Volumio Streaming Daemon May 29 08:21:07 volumio volumio[1245]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 29 08:21:07 volumio volumio[1245]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 29 08:21:07 volumio setdatetime-helper.sh[2061]: Time is not synchronized. Attempting to sync... May 29 08:21:07 volumio sudo[2069]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Thu, 29 May 2025 05:21:07 GMT#015' May 29 08:21:07 volumio sudo[2069]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 29 08:21:07 volumio setdatetime-helper.sh[2070]: Thu May 29 08:21:07 EEST 2025 May 29 08:21:07 volumio setdatetime-helper.sh[2061]: Time synchronized successfully. May 29 08:21:07 volumio sudo[2069]: pam_unix(sudo:session): session closed for user root May 29 08:21:07 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 29 08:21:07 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 29 08:21:07 volumio systemd-journald[502]: Time jumped backwards, rotating. May 29 08:21:07 volumio volumio[1245]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN May 29 08:21:07 volumio volumio[1245]: info: MyVolumio token set successfully May 29 08:21:07 volumio volumio[1245]: info: MYVOLUMIO: Adding device May 29 08:21:07 volumio volumio[1245]: info: MYVOLUMIO: Evaluating Server May 29 08:21:08 volumio volumio[1245]: info: MyVolumio status changed May 29 08:21:08 volumio volumio[1245]: info: Streaming services startup May 29 08:21:08 volumio volumio[1245]: info: Starting Streaming Daemon May 29 08:21:08 volumio volumio[1245]: info: Removing browser output: myVolumio user plan is not superstar May 29 08:21:08 volumio volumio[1245]: info: Removing audio output: May 29 08:21:08 volumio volumio[1245]: info: Stoppping Tunnel 1 May 29 08:21:08 volumio sudo[2090]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 29 08:21:08 volumio sudo[2090]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:21:08 volumio sudo[2092]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service May 29 08:21:08 volumio sudo[2092]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 29 08:21:08 volumio sudo[2090]: pam_unix(sudo:session): session closed for user root May 29 08:21:08 volumio 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. May 29 08:21:08 volumio 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. May 29 08:21:08 volumio volumio[1245]: error: Cannot start Volumio Streaming Daemon May 29 08:21:08 volumio volumio[1245]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 29 08:21:08 volumio volumio[1245]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 29 08:21:08 volumio 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. May 29 08:21:08 volumio 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. May 29 08:21:08 volumio 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. May 29 08:21:08 volumio 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. May 29 08:21:08 volumio 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. May 29 08:21:08 volumio 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. May 29 08:21:08 volumio sudo[2092]: pam_unix(sudo:session): session closed for user root May 29 08:21:08 volumio volumio[1245]: info: Remote SSH Stopped May 29 08:21:08 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 29 08:21:08 volumio volumio[1245]: info: Setting Geolocation for MyVolumio to eu6 May 29 08:21:08 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:08 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:08 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:08 volumio volumio[1245]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} May 29 08:21:09 volumio volumio[1245]: info: Updating MyVolumio device info May 29 08:21:09 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:09 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:09 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:10 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully. May 29 08:21:10 volumio volumio[1245]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} May 29 08:21:11 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 29 08:21:11 volumio volumio[1245]: info: In handleBrowseUri, curUri=spotify May 29 08:21:11 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:11 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:11 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:11 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:11 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. May 29 08:21:12 volumio volumio[1245]: info: MYVOLUMIO: Adding device May 29 08:21:12 volumio volumio[1245]: info: MYVOLUMIO: Evaluating Server May 29 08:21:13 volumio volumio[1245]: info: Setting Geolocation for MyVolumio to eu6 May 29 08:21:13 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:13 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:13 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:13 volumio volumio[1245]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} May 29 08:21:14 volumio volumio[1245]: info: Updating MyVolumio device info May 29 08:21:14 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:14 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:14 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:14 volumio volumio[1245]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} May 29 08:21:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 29 08:21:16 volumio volumio[1245]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 29 08:21:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 29 08:21:16 volumio volumio[1245]: info: Received Get System Version May 29 08:21:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 08:21:16 volumio volumio[1245]: info: Received Get System Info May 29 08:21:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 29 08:21:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 29 08:21:16 volumio volumio[1245]: info: Discovery: Getting this device information May 29 08:21:16 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 29 08:21:16 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 08:21:18 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:18 volumio volumio[1245]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::ClearQueue May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:18 volumio volumio[1245]: info: CorePlayQueue::clearPlayQueue May 29 08:21:18 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:18 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::addQueueItems May 29 08:21:18 volumio volumio[1245]: info: CorePlayQueue::addQueueItems May 29 08:21:18 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:18 volumio volumio[1245]: info: Adding Item to queue: spotify:album:7wdy8JNB5YETxf3UE8fR0r May 29 08:21:18 volumio volumio[1245]: info: Exploding uri spotify:album:7wdy8JNB5YETxf3UE8fR0r in service spop May 29 08:21:18 volumio volumio[1245]: SPOTIFY: EXPLODING URI:spotify:album:7wdy8JNB5YETxf3UE8fR0r May 29 08:21:18 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:18 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::updateTrackBlock May 29 08:21:18 volumio volumio[1245]: info: CorePlayQueue::getTrackBlock May 29 08:21:18 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::play index 0 May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:18 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:18 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:21:18 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:18 volumio volumio[1245]: info: [1748496078535] ControllerSpotify::clearAddPlayTrack May 29 08:21:18 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:21:18 volumio go-librespot[1899]: time="2025-05-29T08:21:18+03:00" level=debug msg="resolved context of track" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:18 volumio go-librespot[1899]: time="2025-05-29T08:21:18+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:18 volumio go-librespot[1899]: time="2025-05-29T08:21:18+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:18 volumio go-librespot[1899]: time="2025-05-29T08:21:18+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:21:18 volumio go-librespot[1899]: time="2025-05-29T08:21:18+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:21:18 volumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4qO2JGY16Psvn6eYSkP67C","play_origin":"go-librespot"}} May 29 08:21:18 volumio go-librespot[1899]: time="2025-05-29T08:21:18+03:00" level=debug msg="selected format OGG_VORBIS_320 (ecae6c13b926af281cf2e614653218f4b472eb43)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:18 volumio go-librespot[1899]: time="2025-05-29T08:21:18+03:00" level=debug msg="requested aes key for file ecae6c13b926af281cf2e614653218f4b472eb43, gid: 4qO2JGY16Psvn6eYSkP67C" May 29 08:21:19 volumio go-librespot[1899]: time="2025-05-29T08:21:19+03:00" level=debug msg="fetched first chunk of 14, total size is 7133088 bytes" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:19 volumio go-librespot[1899]: time="2025-05-29T08:21:19+03:00" level=debug msg="created new output device" May 29 08:21:19 volumio go-librespot[1899]: time="2025-05-29T08:21:19+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 29 08:21:19 volumio go-librespot[1899]: time="2025-05-29T08:21:19+03:00" level=info msg="loaded track \"сонце\" (paused: false, position: 0ms, duration: 191387ms, prefetched: false)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:19 volumio go-librespot[1899]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:21:19 volumio go-librespot[1890]: Aborted May 29 08:21:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:21:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:21:19 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:21:19 volumio volumio[1245]: info: Connection to go-librespot Websocket closed May 29 08:21:20 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 29 08:21:20 volumio volumio[1245]: info: In handleBrowseUri, curUri=spotify:album:7wdy8JNB5YETxf3UE8fR0r May 29 08:21:21 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:21 volumio volumio[1245]: info: Preloading song: spotify:track:4qO2JGY16Psvn6eYSkP67C May 29 08:21:21 volumio volumio[1245]: info: Preloading song: spotify:track:6YRvTrS2q0IjLB9AfRe4XS May 29 08:21:21 volumio volumio[1245]: info: Preloading song: spotify:track:3QrPE4Bl4Uk65dc8ksGIuT May 29 08:21:21 volumio volumio[1245]: info: Preloading song: spotify:track:6OksJLfqxV3fRdwNnwTENT May 29 08:21:21 volumio volumio[1245]: info: Exploding uri spotify:track:4qO2JGY16Psvn6eYSkP67C in service spop May 29 08:21:21 volumio volumio[1245]: SPOTIFY: EXPLODING URI:spotify:track:4qO2JGY16Psvn6eYSkP67C May 29 08:21:21 volumio volumio[1245]: info: No valid Plugin REST Endpoint May 29 08:21:21 volumio volumio[1245]: info: Exploding uri spotify:track:6YRvTrS2q0IjLB9AfRe4XS in service spop May 29 08:21:21 volumio volumio[1245]: SPOTIFY: EXPLODING URI:spotify:track:6YRvTrS2q0IjLB9AfRe4XS May 29 08:21:21 volumio volumio[1245]: info: Exploding uri spotify:track:3QrPE4Bl4Uk65dc8ksGIuT in service spop May 29 08:21:21 volumio volumio[1245]: SPOTIFY: EXPLODING URI:spotify:track:3QrPE4Bl4Uk65dc8ksGIuT May 29 08:21:21 volumio volumio[1245]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4qO2JGY16Psvn6eYSkP67C","service":"spop","name":"сонце","artist":"макс пташник","album":"такі як ми","type":"song","duration":191,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b0a8fe93842fc940cfedafe","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 29 08:21:21 volumio volumio[1245]: info: Exploding uri spotify:track:6OksJLfqxV3fRdwNnwTENT in service spop May 29 08:21:21 volumio volumio[1245]: SPOTIFY: EXPLODING URI:spotify:track:6OksJLfqxV3fRdwNnwTENT May 29 08:21:21 volumio volumio[1245]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6YRvTrS2q0IjLB9AfRe4XS","service":"spop","name":"не питай","artist":"макс пташник","album":"такі як ми","type":"song","duration":241,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b0a8fe93842fc940cfedafe","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 29 08:21:21 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 29 08:21:21 volumio volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 14 May 29 08:21:21 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 29 08:21:21 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:21 volumio volumio[1245]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6OksJLfqxV3fRdwNnwTENT","service":"spop","name":"сонце - Live","artist":"макс пташник","album":"такі як ми","type":"song","duration":342,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b0a8fe93842fc940cfedafe","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 29 08:21:21 volumio volumio[1245]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3QrPE4Bl4Uk65dc8ksGIuT","service":"spop","name":"такі як ми","artist":"макс пташник","album":"такі як ми","type":"song","duration":212,"albumart":"https://i.scdn.co/image/ab67616d0000b2737b0a8fe93842fc940cfedafe","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] May 29 08:21:22 volumio volumio[1245]: info: Initializing connection to go-librespot Websocket May 29 08:21:22 volumio volumio[1245]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:21:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. May 29 08:21:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:21:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:21:22 volumio go-librespot[2142]: go-librespot daemon starting... May 29 08:21:22 volumio go-librespot[2143]: time="2025-05-29T08:21:22+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:21:22 volumio go-librespot[2143]: time="2025-05-29T08:21:22+03:00" level=debug msg="app state loaded" May 29 08:21:22 volumio go-librespot[2143]: time="2025-05-29T08:21:22+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:21:22 volumio go-librespot[2143]: time="2025-05-29T08:21:22+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 29 08:21:22 volumio go-librespot[2143]: time="2025-05-29T08:21:22+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" May 29 08:21:22 volumio go-librespot[2143]: time="2025-05-29T08:21:22+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" May 29 08:21:22 volumio go-librespot[2143]: time="2025-05-29T08:21:22+03:00" level=info msg="zeroconf server listening on port 41457" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="obtained new client token: AAC7hKsXjFHEPzVaBnt7PmVd5zWuHdKCted2aKlolsgRyrgUq5cu5K8sN5zPv/9f+ee6Tz4UwzSmwE22Fk99JzOR5uSaE/YEJYEH6b7sMuFWGrF+Vnnju2vaWBDLoZZop3smhIQghv9DjHH9WwxHdHjdowIbznebec02w7kBFgP9MLsP/17kINYMeIZI4WNWz14W/6sxVsRaoBa+Qs39SFa7wmIjDV/ilumganHshduDqZW0iF8gVPw=" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="completed keyexchange" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="completed challenge" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="dealer connection opened" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=trace msg="starting dealer recv loop" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=trace msg="received accesspoint ping" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="received connection id: ZTQ5NTI3OWEtNjhiMC00NThjLWFiMjQtOGM2ZGU3NGZlMWZiK2RlYWxlcit0Y3A6Ly8wYWNhNDBlMi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNzM1QTMwOTMzQTE0REMxNEMxOTI2MUUwOTlGRjNCRjIxMUVCRjVCQjIwRDhDNkQ1NUI2MjgzOUQ5MDIwNzE5NQ==" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=trace msg="received accesspoint pong ack" May 29 08:21:23 volumio go-librespot[2143]: time="2025-05-29T08:21:23+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:21:25 volumio volumio[1245]: info: Initializing connection to go-librespot Websocket May 29 08:21:25 volumio go-librespot[2143]: time="2025-05-29T08:21:25+03:00" level=debug msg="new websocket client" May 29 08:21:25 volumio volumio[1245]: info: Connection to go-librespot Websocket established May 29 08:21:25 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 08:21:25 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:25 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 29 08:21:25 volumio volumio-remote-updater[809]: No test mode May 29 08:21:25 volumio volumio-remote-updater[809]: No alpha test mode May 29 08:21:25 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled May 29 08:21:26 volumio volumio[1245]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::volumioGetBrowseSources May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 08:21:26 volumio volumio[1245]: error: MyVolumio Plugin failed to authenticate in a timely fashion May 29 08:21:26 volumio volumio[1245]: info: Completed starting MyVolumio Plugin May 29 08:21:26 volumio volumio[1245]: [Metrics] CommandRouter: 38s 601.83ms May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::volumiosetStartupVolume May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::Close All Modals sent May 29 08:21:26 volumio volumio[1245]: info: CoreCommandRouter::Close All Modals sent May 29 08:21:27 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:27 volumio volumio[1245]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::ClearQueue May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:27 volumio volumio[1245]: info: CorePlayQueue::clearPlayQueue May 29 08:21:27 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:27 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::addQueueItems May 29 08:21:27 volumio volumio[1245]: info: CorePlayQueue::addQueueItems May 29 08:21:27 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:27 volumio volumio[1245]: info: Adding Item to queue: spotify:album:7wdy8JNB5YETxf3UE8fR0r May 29 08:21:27 volumio volumio[1245]: info: Using cached record of: spotify:album:7wdy8JNB5YETxf3UE8fR0r May 29 08:21:27 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:27 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::updateTrackBlock May 29 08:21:27 volumio volumio[1245]: info: CorePlayQueue::getTrackBlock May 29 08:21:27 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::play index 0 May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:27 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:27 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:21:27 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:27 volumio volumio[1245]: info: [1748496087186] ControllerSpotify::clearAddPlayTrack May 29 08:21:27 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="resolved context of track" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:21:27 volumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4qO2JGY16Psvn6eYSkP67C","play_origin":"go-librespot"}} May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="selected format OGG_VORBIS_320 (ecae6c13b926af281cf2e614653218f4b472eb43)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="requested aes key for file ecae6c13b926af281cf2e614653218f4b472eb43, gid: 4qO2JGY16Psvn6eYSkP67C" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="fetched first chunk of 14, total size is 7133088 bytes" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="created new output device" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:4qO2JGY16Psvn6eYSkP67C: ALSA error at snd_pcm_open: Device or resource busy" May 29 08:21:27 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:27 volumio go-librespot[2143]: time="2025-05-29T08:21:27+03:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:27 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable May 29 08:21:27 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 29 08:21:27 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect May 29 08:21:28 volumio volumio[1245]: info: Getting Spotify volume May 29 08:21:28 volumio volumio[1245]: info: Spotify volume: 100 May 29 08:21:28 volumio volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 May 29 08:21:28 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:28 volumio volumio[1245]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:21:28 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:28 volumio volumio[1245]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::ClearQueue May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::clearPlayQueue May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:28 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::addQueueItems May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::addQueueItems May 29 08:21:28 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:28 volumio volumio[1245]: info: Adding Item to queue: spotify:track:4qO2JGY16Psvn6eYSkP67C May 29 08:21:28 volumio volumio[1245]: info: Using cached record of: spotify:track:4qO2JGY16Psvn6eYSkP67C May 29 08:21:28 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::updateTrackBlock May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::getTrackBlock May 29 08:21:28 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::play index 0 May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::addQueueItems May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::addQueueItems May 29 08:21:28 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:28 volumio volumio[1245]: info: Adding Item to queue: spotify:track:6YRvTrS2q0IjLB9AfRe4XS May 29 08:21:28 volumio volumio[1245]: info: Using cached record of: spotify:track:6YRvTrS2q0IjLB9AfRe4XS May 29 08:21:28 volumio volumio[1245]: info: Adding Item to queue: spotify:track:3QrPE4Bl4Uk65dc8ksGIuT May 29 08:21:28 volumio volumio[1245]: info: Using cached record of: spotify:track:3QrPE4Bl4Uk65dc8ksGIuT May 29 08:21:28 volumio volumio[1245]: info: Adding Item to queue: spotify:track:6OksJLfqxV3fRdwNnwTENT May 29 08:21:28 volumio volumio[1245]: info: Using cached record of: spotify:track:6OksJLfqxV3fRdwNnwTENT May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:28 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::updateTrackBlock May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::getTrackBlock May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:28 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:21:28 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:28 volumio volumio[1245]: info: [1748496088936] ControllerSpotify::clearAddPlayTrack May 29 08:21:28 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:21:28 volumio go-librespot[2143]: time="2025-05-29T08:21:28+03:00" level=debug msg="resolved context of track" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:28 volumio go-librespot[2143]: time="2025-05-29T08:21:28+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:28 volumio go-librespot[2143]: time="2025-05-29T08:21:28+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:29 volumio go-librespot[2143]: time="2025-05-29T08:21:29+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:21:29 volumio go-librespot[2143]: time="2025-05-29T08:21:29+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:21:29 volumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4qO2JGY16Psvn6eYSkP67C","play_origin":"go-librespot"}} May 29 08:21:29 volumio go-librespot[2143]: time="2025-05-29T08:21:29+03:00" level=debug msg="selected format OGG_VORBIS_320 (ecae6c13b926af281cf2e614653218f4b472eb43)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:29 volumio go-librespot[2143]: time="2025-05-29T08:21:29+03:00" level=debug msg="requested aes key for file ecae6c13b926af281cf2e614653218f4b472eb43, gid: 4qO2JGY16Psvn6eYSkP67C" May 29 08:21:29 volumio go-librespot[2143]: time="2025-05-29T08:21:29+03:00" level=debug msg="fetched first chunk of 14, total size is 7133088 bytes" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:29 volumio go-librespot[2143]: time="2025-05-29T08:21:29+03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:4qO2JGY16Psvn6eYSkP67C: ALSA error at snd_pcm_open: Device or resource busy" May 29 08:21:29 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 29 08:21:29 volumio go-librespot[2143]: time="2025-05-29T08:21:29+03:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:29 volumio go-librespot[2143]: time="2025-05-29T08:21:29+03:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:29 volumio go-librespot[2143]: time="2025-05-29T08:21:29+03:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:32 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:21:32 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:21:32 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:32 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:32 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:21:32 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:32 volumio volumio[1245]: info: [1748496092402] ControllerSpotify::clearAddPlayTrack May 29 08:21:32 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=debug msg="resolved context of track" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:21:32 volumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4qO2JGY16Psvn6eYSkP67C","play_origin":"go-librespot"}} May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=debug msg="selected format OGG_VORBIS_320 (ecae6c13b926af281cf2e614653218f4b472eb43)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=debug msg="requested aes key for file ecae6c13b926af281cf2e614653218f4b472eb43, gid: 4qO2JGY16Psvn6eYSkP67C" May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=debug msg="fetched first chunk of 14, total size is 7133088 bytes" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 29 08:21:32 volumio go-librespot[2143]: time="2025-05-29T08:21:32+03:00" level=info msg="loaded track \"сонце\" (paused: false, position: 0ms, duration: 191387ms, prefetched: false)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:32 volumio go-librespot[2143]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:21:32 volumio go-librespot[2142]: Aborted May 29 08:21:32 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:21:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:21:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:21:32 volumio volumio[1245]: info: Connection to go-librespot Websocket closed May 29 08:21:33 volumio volumio[1245]: info: BOOT COMPLETED May 29 08:21:35 volumio volumio[1245]: info: Initializing connection to go-librespot Websocket May 29 08:21:35 volumio volumio[1245]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:21:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. May 29 08:21:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:21:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:21:35 volumio go-librespot[2176]: go-librespot daemon starting... May 29 08:21:35 volumio go-librespot[2177]: time="2025-05-29T08:21:35+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:21:35 volumio go-librespot[2177]: time="2025-05-29T08:21:35+03:00" level=debug msg="app state loaded" May 29 08:21:35 volumio go-librespot[2177]: time="2025-05-29T08:21:35+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:21:36 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:21:36 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:21:36 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:36 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:36 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:21:36 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:36 volumio volumio[1245]: info: [1748496096022] ControllerSpotify::clearAddPlayTrack May 29 08:21:36 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=info msg="zeroconf server listening on port 36115" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="obtained new client token: AAAAZl1+UBiS4aIb8AgfayKJuAc2PJvhppmqEZbqna7UAiEg+D4nMCTcntNemF4ts8LMBjsJksqzuwS4CS8IZz2bKDvLAqNDufkq7x7yUNiy3kYbvWVzHZb+bCHH3XabFRnnFU+8UuDxrBTOeJTGEOEwqErR9eUSjMqnpQzGDxd9spdjcpJsf6zCTlR1ns7IT4dctArcqlvksY0eRGIA5cWVEJ+fRUDEPSuFIKlb8yT1/dK5eLNjiik=" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="completed keyexchange" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="completed challenge" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="dealer connection opened" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=trace msg="starting dealer recv loop" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=trace msg="received accesspoint ping" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="resolved context of track" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:36 volumio go-librespot[2177]: time="2025-05-29T08:21:36+03:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" May 29 08:21:36 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. May 29 08:21:37 volumio go-librespot[2177]: time="2025-05-29T08:21:37+03:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" May 29 08:21:38 volumio volumio[1245]: info: Initializing connection to go-librespot Websocket May 29 08:21:38 volumio go-librespot[2177]: time="2025-05-29T08:21:38+03:00" level=debug msg="new websocket client" May 29 08:21:38 volumio volumio[1245]: info: Connection to go-librespot Websocket established May 29 08:21:38 volumio go-librespot[2177]: time="2025-05-29T08:21:38+03:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" May 29 08:21:38 volumio go-librespot[2177]: time="2025-05-29T08:21:38+03:00" level=error msg="failed put state after update" error="put state request failed with status 400: Require at least one of callback url or connection id" May 29 08:21:38 volumio go-librespot[2177]: time="2025-05-29T08:21:38+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:21:38 volumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4qO2JGY16Psvn6eYSkP67C","play_origin":"go-librespot"}} May 29 08:21:38 volumio go-librespot[2177]: time="2025-05-29T08:21:38+03:00" level=debug msg="selected format OGG_VORBIS_320 (ecae6c13b926af281cf2e614653218f4b472eb43)" uri="spotify:track:4qO2JGY16Psvn6eYSkP67C" May 29 08:21:38 volumio go-librespot[2177]: time="2025-05-29T08:21:38+03:00" level=debug msg="requested aes key for file ecae6c13b926af281cf2e614653218f4b472eb43, gid: 4qO2JGY16Psvn6eYSkP67C" May 29 08:21:41 volumio volumio[1245]: info: Getting Spotify volume May 29 08:21:41 volumio volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 May 29 08:21:41 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 29 08:21:41 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:41 volumio volumio[1245]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:21:48 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 29 08:21:48 volumio volumio[1245]: info: In handleBrowseUri, curUri=spotify May 29 08:21:48 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:48 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:48 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:48 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:51 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri May 29 08:21:51 volumio volumio[1245]: info: In handleBrowseUri, curUri=spotify/myalbums May 29 08:21:52 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:53 volumio go-librespot[2177]: time="2025-05-29T08:21:53+03:00" level=debug msg="received connection id: MThhZGRiOTItY2FmMi00ZWFmLWExNDUtNDkzZmNiNjZjNzQ4K2RlYWxlcit0Y3A6Ly8wYWNhNDE2Mi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMjVFREQ2MDY3NjFCRDMwMzNDNjFBQTE3MTk2MEQ1RDc0Mjk3QzdBRUJEQjc2ODBGRjE2QTM0MDlGNEM4NjdGMw==" May 29 08:21:53 volumio go-librespot[2177]: time="2025-05-29T08:21:53+03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4qO2JGY16Psvn6eYSkP67C: failed retrieving audio key: context deadline exceeded" May 29 08:21:53 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 29 08:21:53 volumio volumio[1245]: info: Spotify volume: 100 May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=trace msg="received accesspoint pong ack" May 29 08:21:54 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:54 volumio volumio[1245]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::ClearQueue May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:54 volumio volumio[1245]: info: CorePlayQueue::clearPlayQueue May 29 08:21:54 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:54 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::addQueueItems May 29 08:21:54 volumio volumio[1245]: info: CorePlayQueue::addQueueItems May 29 08:21:54 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:54 volumio volumio[1245]: info: Adding Item to queue: spotify:album:1N6uOXF9LDPMF6DNAm2eSt May 29 08:21:54 volumio volumio[1245]: info: Exploding uri spotify:album:1N6uOXF9LDPMF6DNAm2eSt in service spop May 29 08:21:54 volumio volumio[1245]: SPOTIFY: EXPLODING URI:spotify:album:1N6uOXF9LDPMF6DNAm2eSt May 29 08:21:54 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:54 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::updateTrackBlock May 29 08:21:54 volumio volumio[1245]: info: CorePlayQueue::getTrackBlock May 29 08:21:54 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::play index 0 May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:54 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:54 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:21:54 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:54 volumio volumio[1245]: info: [1748496114365] ControllerSpotify::clearAddPlayTrack May 29 08:21:54 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=debug msg="resolved context of track" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:21:54 volumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6dBSnKDl4KlDGAiGsiglic","play_origin":"go-librespot"}} May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=debug msg="selected format OGG_VORBIS_320 (dc4b4b5a6744020e9c3f5b76ef594b83515fab18)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:21:54 volumio go-librespot[2177]: time="2025-05-29T08:21:54+03:00" level=debug msg="requested aes key for file dc4b4b5a6744020e9c3f5b76ef594b83515fab18, gid: 6dBSnKDl4KlDGAiGsiglic" May 29 08:21:55 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:55 volumio volumio[1245]: info: CoreCommandRouter::volumioReplaceandPlayItems May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::ClearQueue May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:55 volumio volumio[1245]: info: CorePlayQueue::clearPlayQueue May 29 08:21:55 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:55 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::addQueueItems May 29 08:21:55 volumio volumio[1245]: info: CorePlayQueue::addQueueItems May 29 08:21:55 volumio volumio[1245]: info: Preload queue cleared May 29 08:21:55 volumio volumio[1245]: info: Adding Item to queue: spotify:album:1N6uOXF9LDPMF6DNAm2eSt May 29 08:21:55 volumio volumio[1245]: info: Using cached record of: spotify:album:1N6uOXF9LDPMF6DNAm2eSt May 29 08:21:55 volumio volumio[1245]: info: CoreCommandRouter::volumioPushQueue May 29 08:21:55 volumio volumio[1245]: info: CorePlayQueue::saveQueue May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::updateTrackBlock May 29 08:21:55 volumio volumio[1245]: info: CorePlayQueue::getTrackBlock May 29 08:21:55 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::play index 0 May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::stop May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:55 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:55 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:21:55 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:55 volumio volumio[1245]: info: [1748496115167] ControllerSpotify::clearAddPlayTrack May 29 08:21:55 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:21:56 volumio go-librespot[2177]: time="2025-05-29T08:21:56+03:00" level=debug msg="fetched first chunk of 22, total size is 11367558 bytes" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:21:56 volumio go-librespot[2177]: time="2025-05-29T08:21:56+03:00" level=debug msg="created new output device" May 29 08:21:56 volumio go-librespot[2177]: time="2025-05-29T08:21:56+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 29 08:21:56 volumio go-librespot[2177]: time="2025-05-29T08:21:56+03:00" level=info msg="loaded track \"Все було так - Live\" (paused: false, position: 0ms, duration: 282631ms, prefetched: false)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:21:56 volumio go-librespot[2177]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:21:56 volumio go-librespot[2176]: Aborted May 29 08:21:56 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:21:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:21:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:21:56 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:21:56 volumio volumio[1245]: info: Connection to go-librespot Websocket closed May 29 08:21:59 volumio volumio[1245]: info: Initializing connection to go-librespot Websocket May 29 08:21:59 volumio volumio[1245]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:21:59 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:21:59 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:21:59 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:21:59 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:59 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:21:59 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:21:59 volumio volumio[1245]: info: [1748496119265] ControllerSpotify::clearAddPlayTrack May 29 08:21:59 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:21:59 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:21:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. May 29 08:21:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:21:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:21:59 volumio go-librespot[2217]: go-librespot daemon starting... May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=debug msg="app state loaded" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=info msg="zeroconf server listening on port 44995" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=debug msg="obtained new client token: AAB6aIwEujDL1d3t8DMGDCrEFjWU0zQlkH3SgehL93NIv/kmhn3J6JeqBjNvNlPd9SN4+9KMcYNI9vDHmBeQQRIESq88Ho68Ay/GO1qNM4RO4TGgL8FWLJtP5Tap5ALTHib77jVLYQm42geHKkhfHN3zIps1SVxoZWV4lCL5t7cOaiXac6w2lqI17Q3NfDBBp/271dF3J7sZyENnPCmKt5YKyFkRfhDNhRR5hJDv11WMu7RogdsC" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=debug msg="completed keyexchange" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=debug msg="completed challenge" May 29 08:21:59 volumio go-librespot[2218]: time="2025-05-29T08:21:59+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=debug msg="dealer connection opened" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=trace msg="starting dealer recv loop" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=trace msg="received accesspoint ping" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=debug msg="received connection id: NDI0M2RkNTQtMmFlNC00OTY3LTkzOWQtN2UyODcxNGE5NTVhK2RlYWxlcit0Y3A6Ly8wYWNhNDE5MS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMjdEQjkxRDFFMjZBRjY2RUE5OUM2QThCQzJBRDQ5ODA2NDIzRjIwQzE3ODJDNUZBQ0E1NUY5NTQwMkY0QjM3NA==" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=trace msg="received accesspoint pong ack" May 29 08:22:00 volumio go-librespot[2218]: time="2025-05-29T08:22:00+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:22:02 volumio volumio[1245]: info: Initializing connection to go-librespot Websocket May 29 08:22:02 volumio go-librespot[2218]: time="2025-05-29T08:22:02+03:00" level=debug msg="new websocket client" May 29 08:22:02 volumio volumio[1245]: info: Connection to go-librespot Websocket established May 29 08:22:05 volumio volumio[1245]: info: Getting Spotify volume May 29 08:22:05 volumio volumio[1245]: info: Spotify volume: 100 May 29 08:22:05 volumio volumio[1245]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 May 29 08:22:05 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 29 08:22:05 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:22:05 volumio volumio[1245]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 29 08:22:05 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:22:05 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:22:05 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:22:05 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:22:05 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:22:05 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:22:05 volumio volumio[1245]: info: [1748496125891] ControllerSpotify::clearAddPlayTrack May 29 08:22:05 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:22:05 volumio go-librespot[2218]: time="2025-05-29T08:22:05+03:00" level=debug msg="resolved context of track" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:05 volumio go-librespot[2218]: time="2025-05-29T08:22:05+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:05 volumio go-librespot[2218]: time="2025-05-29T08:22:05+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:06 volumio go-librespot[2218]: time="2025-05-29T08:22:06+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:22:06 volumio go-librespot[2218]: time="2025-05-29T08:22:06+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:22:06 volumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6dBSnKDl4KlDGAiGsiglic","play_origin":"go-librespot"}} May 29 08:22:06 volumio go-librespot[2218]: time="2025-05-29T08:22:06+03:00" level=debug msg="selected format OGG_VORBIS_320 (dc4b4b5a6744020e9c3f5b76ef594b83515fab18)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:06 volumio go-librespot[2218]: time="2025-05-29T08:22:06+03:00" level=debug msg="requested aes key for file dc4b4b5a6744020e9c3f5b76ef594b83515fab18, gid: 6dBSnKDl4KlDGAiGsiglic" May 29 08:22:06 volumio go-librespot[2218]: time="2025-05-29T08:22:06+03:00" level=debug msg="fetched first chunk of 22, total size is 11367558 bytes" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:06 volumio go-librespot[2218]: time="2025-05-29T08:22:06+03:00" level=debug msg="created new output device" May 29 08:22:06 volumio go-librespot[2218]: time="2025-05-29T08:22:06+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 29 08:22:06 volumio go-librespot[2218]: time="2025-05-29T08:22:06+03:00" level=info msg="loaded track \"Все було так - Live\" (paused: false, position: 0ms, duration: 282631ms, prefetched: false)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:06 volumio go-librespot[2218]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:22:06 volumio go-librespot[2217]: Aborted May 29 08:22:06 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:22:06 volumio volumio[1245]: info: Connection to go-librespot Websocket closed May 29 08:22:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:22:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:22:06 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:22:06 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:22:06 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:22:06 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:22:06 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:22:06 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:22:06 volumio volumio[1245]: info: [1748496126884] ControllerSpotify::clearAddPlayTrack May 29 08:22:06 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:22:06 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:22:07 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:22:07 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:22:07 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:22:07 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:22:07 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:22:07 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:22:07 volumio volumio[1245]: info: [1748496127070] ControllerSpotify::clearAddPlayTrack May 29 08:22:07 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:22:07 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:22:09 volumio volumio[1245]: info: Initializing connection to go-librespot Websocket May 29 08:22:09 volumio volumio[1245]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:22:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. May 29 08:22:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 29 08:22:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 29 08:22:09 volumio go-librespot[2243]: go-librespot daemon starting... May 29 08:22:09 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... May 29 08:22:09 volumio go-librespot[2244]: time="2025-05-29T08:22:09+03:00" level=info msg="running go-librespot 0.2.0" May 29 08:22:09 volumio go-librespot[2244]: time="2025-05-29T08:22:09+03:00" level=debug msg="app state loaded" May 29 08:22:09 volumio go-librespot[2244]: time="2025-05-29T08:22:09+03:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 08:22:09 volumio dbus-daemon[803]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.26' (uid=0 pid=2251 comm="timedatectl show --property=NTPSynchronized --valu") May 29 08:22:09 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... May 29 08:22:09 volumio dbus-daemon[803]: [system] Successfully activated service 'org.freedesktop.timedate1' May 29 08:22:09 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. May 29 08:22:09 volumio setdatetime-helper.sh[2245]: Time is not synchronized. Attempting to sync... May 29 08:22:09 volumio go-librespot[2244]: time="2025-05-29T08:22:09+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" May 29 08:22:09 volumio go-librespot[2244]: time="2025-05-29T08:22:09+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 08:22:09 volumio go-librespot[2244]: time="2025-05-29T08:22:09+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 08:22:09 volumio go-librespot[2244]: time="2025-05-29T08:22:09+03:00" level=info msg="zeroconf server listening on port 34723" May 29 08:22:09 volumio sudo[2260]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Thu, 29 May 2025 05:22:10 GMT#015' May 29 08:22:09 volumio sudo[2260]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 29 08:22:10 volumio setdatetime-helper.sh[2261]: Thu May 29 08:22:10 EEST 2025 May 29 08:22:10 volumio sudo[2260]: pam_unix(sudo:session): session closed for user root May 29 08:22:10 volumio setdatetime-helper.sh[2245]: Time synchronized successfully. May 29 08:22:10 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. May 29 08:22:10 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="obtained new client token: AABzXUCjjhckjORlcetCis1oOogdz57B35Ys0/I7UD/Q8KQNIKPZwcRvMYiTX0f2DklWS89U+TLtQBxgHCJSvybKwZwO1E374y/T34bxHGNfKILFg0cLCIGSKag0X1H05JDmkms6kKbpv6CX5l9UZTspZH68Y8BbGnjbi1qPOga8G2/KiRb0de2OJICrfjihWqDRPtcwPSNKZgMO4Hsqu/6maZ6r9cIp9SFgc3rNEZuHUEGfjr/UbRE=" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="completed keyexchange" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="completed challenge" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=info msg="authenticated AP as pb5pp9zr5gss9vfrrdysusbut" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=info msg="authenticated Login5 as pb5pp9zr5gss9vfrrdysusbut" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="initializing zeroconf session, username: pb5pp9zr5gss9vfrrdysusbut" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="dealer connection opened" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=trace msg="starting accesspoint recv loop" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=trace msg="starting dealer recv loop" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=trace msg="received accesspoint ping" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="received connection id: Y2UxNGEyNDEtZTU3MC00NzZmLTllZmYtM2QwYWRiOWU4MDA3K2RlYWxlcit0Y3A6Ly8wYWNhNDE2Mi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMjc5MUUwNTQ3NjVFQkZBQjk2NzdBQUFGQjcxODI4NzlEMkZGMzczNTFCNkEzQUI2NEI4QkVENkRDQTZDQkIwMA==" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=trace msg="received accesspoint pong ack" May 29 08:22:10 volumio go-librespot[2244]: time="2025-05-29T08:22:10+03:00" level=debug msg="put connect state because NEW_DEVICE" May 29 08:22:12 volumio volumio[1245]: info: Initializing connection to go-librespot Websocket May 29 08:22:12 volumio go-librespot[2244]: time="2025-05-29T08:22:12+03:00" level=debug msg="new websocket client" May 29 08:22:12 volumio volumio[1245]: info: Connection to go-librespot Websocket established May 29 08:22:14 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 29 08:22:14 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 29 08:22:14 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 29 08:22:14 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:22:14 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 29 08:22:14 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 29 08:22:14 volumio volumio[1245]: info: [1748496134768] ControllerSpotify::clearAddPlayTrack May 29 08:22:14 volumio volumio[1245]: info: Sending Spotify command with payload to local API: /player/play May 29 08:22:14 volumio go-librespot[2244]: time="2025-05-29T08:22:14+03:00" level=debug msg="resolved context of track" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:14 volumio go-librespot[2244]: time="2025-05-29T08:22:14+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:14 volumio go-librespot[2244]: time="2025-05-29T08:22:14+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:14 volumio go-librespot[2244]: time="2025-05-29T08:22:14+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 08:22:14 volumio go-librespot[2244]: time="2025-05-29T08:22:14+03:00" level=trace msg="emitting websocket event: will_play" May 29 08:22:14 volumio volumio[1245]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6dBSnKDl4KlDGAiGsiglic","play_origin":"go-librespot"}} May 29 08:22:14 volumio go-librespot[2244]: time="2025-05-29T08:22:14+03:00" level=debug msg="selected format OGG_VORBIS_320 (dc4b4b5a6744020e9c3f5b76ef594b83515fab18)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:15 volumio go-librespot[2244]: time="2025-05-29T08:22:15+03:00" level=debug msg="requested aes key for file dc4b4b5a6744020e9c3f5b76ef594b83515fab18, gid: 6dBSnKDl4KlDGAiGsiglic" May 29 08:22:15 volumio go-librespot[2244]: time="2025-05-29T08:22:15+03:00" level=debug msg="fetched first chunk of 22, total size is 11367558 bytes" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:15 volumio go-librespot[2244]: time="2025-05-29T08:22:15+03:00" level=debug msg="created new output device" May 29 08:22:15 volumio go-librespot[2244]: time="2025-05-29T08:22:15+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 29 08:22:15 volumio go-librespot[2244]: time="2025-05-29T08:22:15+03:00" level=info msg="loaded track \"Все було так - Live\" (paused: false, position: 0ms, duration: 282631ms, prefetched: false)" uri="spotify:track:6dBSnKDl4KlDGAiGsiglic" May 29 08:22:15 volumio go-librespot[2244]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. May 29 08:22:15 volumio go-librespot[2243]: Aborted May 29 08:22:15 volumio volumio[1245]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up May 29 08:22:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a May 29 08:22:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 29 08:22:15 volumio volumio[1245]: info: Connection to go-librespot Websocket closed May 29 08:22:15 volumio volumio[1245]: info: Getting Spotify volume May 29 08:22:15 volumio volumio[1245]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 08:22:15 volumio volumio[1245]: Error: connect ECONNREFUSED 127.0.0.1:9879 May 29 08:22:15 volumio volumio[1245]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { May 29 08:22:15 volumio volumio[1245]: errno: -111, May 29 08:22:15 volumio volumio[1245]: code: 'ECONNREFUSED', May 29 08:22:15 volumio volumio[1245]: syscall: 'connect', May 29 08:22:15 volumio volumio[1245]: address: '127.0.0.1', May 29 08:22:15 volumio volumio[1245]: port: 9879, May 29 08:22:15 volumio volumio[1245]: response: undefined May 29 08:22:15 volumio volumio[1245]: } May 29 08:22:15 volumio volumio[1245]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 08:22:15 volumio sudo[2293]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-05-29 08:21' May 29 08:22:15 volumio sudo[2293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="fd567ba9bc0dc34c0403e2d5b72a0f46467d1983" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri May 23 07:33:33 UTC 2025" VOLUMIO_VERSION="0.069" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="d67a2da4ffe3f001e986b1f31eaa3a76"