-- Logs begin at Thu 2019-02-14 12:11:58 EET, end at Fri 2026-03-27 21:56:43 EET. -- Mar 27 21:55:01 volumio go-librespot[1101]: time="2026-03-27T21:55:01+02:00" level=trace msg="sent dealer ping" Mar 27 21:55:01 volumio go-librespot[1101]: time="2026-03-27T21:55:01+02:00" level=trace msg="received dealer pong" Mar 27 21:55:22 volumio kernel: usb 1-1.1: new high-speed USB device number 21 using xhci_hcd Mar 27 21:55:22 volumio kernel: usb 1-1.1: device descriptor read/64, error -71 Mar 27 21:55:22 volumio kernel: usb 1-1.1: device descriptor read/64, error -71 Mar 27 21:55:23 volumio kernel: usb 1-1.1: new high-speed USB device number 22 using xhci_hcd Mar 27 21:55:23 volumio kernel: usb 1-1.1: device descriptor read/64, error -71 Mar 27 21:55:23 volumio kernel: usb 1-1.1: device descriptor read/64, error -71 Mar 27 21:55:23 volumio kernel: usb 1-1-port1: attempt power cycle Mar 27 21:55:24 volumio kernel: usb 1-1.1: new high-speed USB device number 23 using xhci_hcd Mar 27 21:55:24 volumio kernel: usb 1-1.1: Device not responding to setup address. Mar 27 21:55:24 volumio kernel: usb 1-1.1: Device not responding to setup address. Mar 27 21:55:24 volumio kernel: usb 1-1.1: device not accepting address 23, error -71 Mar 27 21:55:24 volumio kernel: usb 1-1.1: new high-speed USB device number 24 using xhci_hcd Mar 27 21:55:24 volumio kernel: usb 1-1.1: Device not responding to setup address. Mar 27 21:55:25 volumio kernel: usb 1-1.1: Device not responding to setup address. Mar 27 21:55:25 volumio kernel: usb 1-1.1: device not accepting address 24, error -71 Mar 27 21:55:25 volumio kernel: usb 1-1-port1: unable to enumerate USB device Mar 27 21:55:25 volumio kernel: usb 1-1.3: new high-speed USB device number 25 using xhci_hcd Mar 27 21:55:25 volumio kernel: usb 1-1.3: device descriptor read/64, error -71 Mar 27 21:55:25 volumio kernel: usb 1-1.3: device descriptor read/64, error -71 Mar 27 21:55:26 volumio kernel: usb 1-1.3: new high-speed USB device number 26 using xhci_hcd Mar 27 21:55:26 volumio kernel: usb 1-1.3: device descriptor read/64, error -71 Mar 27 21:55:26 volumio kernel: usb 1-1.3: device descriptor read/64, error -71 Mar 27 21:55:26 volumio kernel: usb 1-1-port3: attempt power cycle Mar 27 21:55:27 volumio kernel: usb 1-1.3: new high-speed USB device number 27 using xhci_hcd Mar 27 21:55:27 volumio kernel: usb 1-1.3: Device not responding to setup address. Mar 27 21:55:27 volumio kernel: usb 1-1.3: Device not responding to setup address. Mar 27 21:55:27 volumio kernel: usb 1-1.3: device not accepting address 27, error -71 Mar 27 21:55:27 volumio kernel: usb 1-1.3: new high-speed USB device number 28 using xhci_hcd Mar 27 21:55:27 volumio kernel: usb 1-1.3: Device not responding to setup address. Mar 27 21:55:27 volumio kernel: usb 1-1.3: Device not responding to setup address. Mar 27 21:55:28 volumio kernel: usb 1-1.3: device not accepting address 28, error -71 Mar 27 21:55:28 volumio kernel: usb 1-1-port3: unable to enumerate USB device Mar 27 21:55:31 volumio go-librespot[1101]: time="2026-03-27T21:55:31+02:00" level=trace msg="sent dealer ping" Mar 27 21:55:31 volumio go-librespot[1101]: time="2026-03-27T21:55:31+02:00" level=trace msg="received dealer pong" Mar 27 21:55:39 volumio volumio[840]: verbose: New Socket.io Connection to 192.168.1.248:3000 from 192.168.1.186 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Mar 27 21:55:41 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:41 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:41 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:41 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:41 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:55:41 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:41 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:41 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:41 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:41 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:55:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:42 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:42 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:55:42 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 27 21:55:42 volumio volumio[840]: verbose: New Socket.io Connection to 192.168.1.248:3000 from 192.168.1.186 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Mar 27 21:55:43 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableLanguages Mar 27 21:55:43 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 21:55:43 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 21:55:43 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Mar 27 21:55:43 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Mar 27 21:55:43 volumio sudo[5885]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Mar 27 21:55:43 volumio sudo[5885]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:43 volumio sudo[5891]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Mar 27 21:55:43 volumio sudo[5885]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:43 volumio sudo[5891]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:43 volumio sudo[5891]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:43 volumio sudo[5898]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Mar 27 21:55:43 volumio sudo[5898]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:43 volumio sudo[5898]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:43 volumio sudo[5905]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Mar 27 21:55:43 volumio sudo[5905]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:43 volumio sudo[5905]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:43 volumio sudo[5911]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 21:55:43 volumio sudo[5911]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:43 volumio sudo[5911]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:43 volumio sudo[5914]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 21:55:43 volumio sudo[5914]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:43 volumio sudo[5914]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:43 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 21:55:43 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:44 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:44 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:55:44 volumio volumio[840]: verbose: New Socket.io Connection to 192.168.1.248:3000 from 192.168.1.186 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 21:55:44 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 21:55:46 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 21:55:46 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 21:55:47 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:47 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:47 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:47 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:47 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:55:48 volumio sudo[5917]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 21:55:48 volumio sudo[5917]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:48 volumio sudo[5917]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:48 volumio volumio[840]: verbose: New Socket.io Connection to 192.168.1.248:3000 from 192.168.1.186 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Mar 27 21:55:48 volumio sudo[5920]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 21:55:48 volumio sudo[5920]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:48 volumio sudo[5920]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:49 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 21:55:49 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 21:55:49 volumio volumio[840]: verbose: New Socket.io Connection to 192.168.1.248 from 192.168.1.186 UA: Mozilla/5.0 (Linux; Android 16; SM-A346B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.119 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Mar 27 21:55:51 volumio sudo[5923]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 21:55:51 volumio sudo[5923]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:51 volumio sudo[5923]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:51 volumio sudo[5926]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 21:55:51 volumio sudo[5926]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 27 21:55:51 volumio sudo[5926]: pam_unix(sudo:session): session closed for user root Mar 27 21:55:51 volumio volumio[840]: verbose: New Socket.io Connection to 192.168.1.248 from 192.168.1.186 UA: Mozilla/5.0 (Linux; Android 16; SM-A346B Build/BP2A.250605.031.A3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.119 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Mar 27 21:55:52 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:52 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 27 21:55:52 volumio volumio[840]: info: Listing playlists Mar 27 21:55:52 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 27 21:55:52 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 21:55:52 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 21:55:52 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 27 21:55:53 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 21:55:53 volumio volumio[840]: info: Received Get System Info Mar 27 21:55:53 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:53 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:53 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:53 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:53 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:55:53 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 21:55:57 volumio volumio[840]: info: Received Get System Info Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:57 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 21:55:57 volumio volumio[840]: info: Received Get System Info Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:57 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 21:55:57 volumio volumio[840]: info: Received Get System Info Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:55:57 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:55:57 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:56:01 volumio go-librespot[1101]: time="2026-03-27T21:56:01+02:00" level=trace msg="sent dealer ping" Mar 27 21:56:01 volumio go-librespot[1101]: time="2026-03-27T21:56:01+02:00" level=trace msg="received dealer pong" Mar 27 21:56:06 volumio go-librespot[1101]: time="2026-03-27T21:56:06+02:00" level=debug msg="handling resume player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:06 volumio go-librespot[1101]: time="2026-03-27T21:56:06+02:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:06 volumio go-librespot[1101]: time="2026-03-27T21:56:06+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:06 volumio go-librespot[1101]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 27 21:56:06 volumio go-librespot[1101]: time="2026-03-27T21:56:06+02:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such device" Mar 27 21:56:08 volumio go-librespot[1101]: time="2026-03-27T21:56:08+02:00" level=debug msg="handling resume player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:08 volumio go-librespot[1101]: time="2026-03-27T21:56:08+02:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:08 volumio go-librespot[1101]: time="2026-03-27T21:56:08+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:08 volumio go-librespot[1101]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 27 21:56:08 volumio go-librespot[1101]: time="2026-03-27T21:56:08+02:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such device" Mar 27 21:56:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 27 21:56:12 volumio volumio[840]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 27 21:56:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 27 21:56:12 volumio volumio[840]: info: Received Get System Version Mar 27 21:56:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 21:56:12 volumio volumio[840]: info: Received Get System Info Mar 27 21:56:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 21:56:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 21:56:12 volumio volumio[840]: info: Discovery: Getting this device information Mar 27 21:56:12 volumio volumio[840]: info: CoreCommandRouter::volumioGetState Mar 27 21:56:12 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 21:56:16 volumio go-librespot[1101]: time="2026-03-27T21:56:16+02:00" level=debug msg="handling skip_prev player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:16 volumio go-librespot[1101]: time="2026-03-27T21:56:16+02:00" level=debug msg="skip previous track" Mar 27 21:56:16 volumio go-librespot[1101]: time="2026-03-27T21:56:16+02:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:16 volumio go-librespot[1101]: time="2026-03-27T21:56:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:16 volumio go-librespot[1101]: time="2026-03-27T21:56:16+02:00" level=trace msg="emitting websocket event: will_play" Mar 27 21:56:16 volumio go-librespot[1101]: time="2026-03-27T21:56:16+02:00" level=debug msg="selected format OGG_VORBIS_320 (196438b4fb225ebf9ac0c34f06b62a3a37817d13)" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:16 volumio go-librespot[1101]: time="2026-03-27T21:56:16+02:00" level=debug msg="requested aes key for file 196438b4fb225ebf9ac0c34f06b62a3a37817d13, gid: 4DDyybdhC9su038YIG6JDj" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=debug msg="fetched first chunk of 24, total size is 12472518 bytes" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=info msg="loaded track \"So Far Away - Remastered 1996\" (paused: true, position: 0ms, duration: 306373ms, prefetched: false)" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=trace msg="emitting websocket event: metadata" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=debug msg="sending successful reply for dealer request" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:17 volumio go-librespot[1101]: time="2026-03-27T21:56:17+02:00" level=trace msg="emitting websocket event: paused" Mar 27 21:56:17 volumio volumio[840]: info: CoreCommandRouter::servicePushState Mar 27 21:56:17 volumio volumio[840]: info: CoreStateMachine::pushState Mar 27 21:56:17 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 21:56:17 volumio volumio[840]: info: CoreCommandRouter::volumioPushState Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="handling skip_prev player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="skip previous track" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=trace msg="emitting websocket event: will_play" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="selected format OGG_VORBIS_320 (95f166cf211b4af0322546e947c44a7e6ded89ef)" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="requested aes key for file 95f166cf211b4af0322546e947c44a7e6ded89ef, gid: 3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=trace msg="received accesspoint ping" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="fetched first chunk of 23, total size is 11592040 bytes" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=info msg="loaded track \"Chan Chan\" (paused: true, position: 0ms, duration: 258693ms, prefetched: false)" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=trace msg="received accesspoint pong ack" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=trace msg="emitting websocket event: metadata" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="sending successful reply for dealer request" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:18 volumio go-librespot[1101]: time="2026-03-27T21:56:18+02:00" level=trace msg="emitting websocket event: paused" Mar 27 21:56:18 volumio volumio[840]: info: CoreCommandRouter::servicePushState Mar 27 21:56:18 volumio volumio[840]: info: CoreStateMachine::pushState Mar 27 21:56:18 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 21:56:18 volumio volumio[840]: info: CoreCommandRouter::volumioPushState Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="handling skip_prev player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="skip previous track" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=trace msg="emitting websocket event: will_play" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="selected format OGG_VORBIS_320 (86a3d5ada5242baeffb5c12964d9e3ea8e68490b)" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="requested aes key for file 86a3d5ada5242baeffb5c12964d9e3ea8e68490b, gid: 0j5FJJOmmnXPd0XajFWkMF" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="fetched first chunk of 23, total size is 11773164 bytes" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=info msg="loaded track \"Unfinished Sympathy - 2012 Mix/Master\" (paused: true, position: 0ms, duration: 308426ms, prefetched: false)" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:0j5FJJOmmnXPd0XajFWkMF" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=trace msg="emitting websocket event: metadata" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="sending successful reply for dealer request" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:19 volumio go-librespot[1101]: time="2026-03-27T21:56:19+02:00" level=trace msg="emitting websocket event: paused" Mar 27 21:56:19 volumio volumio[840]: info: CoreCommandRouter::servicePushState Mar 27 21:56:19 volumio volumio[840]: info: CoreStateMachine::pushState Mar 27 21:56:19 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 21:56:19 volumio volumio[840]: info: CoreCommandRouter::volumioPushState Mar 27 21:56:20 volumio go-librespot[1101]: time="2026-03-27T21:56:20+02:00" level=debug msg="handling skip_next player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:20 volumio go-librespot[1101]: time="2026-03-27T21:56:20+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:20 volumio go-librespot[1101]: time="2026-03-27T21:56:20+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:20 volumio go-librespot[1101]: time="2026-03-27T21:56:20+02:00" level=trace msg="emitting websocket event: will_play" Mar 27 21:56:20 volumio go-librespot[1101]: time="2026-03-27T21:56:20+02:00" level=debug msg="selected format OGG_VORBIS_320 (95f166cf211b4af0322546e947c44a7e6ded89ef)" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:20 volumio go-librespot[1101]: time="2026-03-27T21:56:20+02:00" level=debug msg="requested aes key for file 95f166cf211b4af0322546e947c44a7e6ded89ef, gid: 3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="fetched first chunk of 23, total size is 11592040 bytes" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:21 volumio go-librespot[1101]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:3bxZhauuIU4ubctdRZwPYW): failed setting stream for spotify:track:3bxZhauuIU4ubctdRZwPYW: ALSA error at snd_pcm_open: No such device" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:3bxZhauuIU4ubctdRZwPYW" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="handling skip_next player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=trace msg="emitting websocket event: will_play" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="selected format OGG_VORBIS_320 (196438b4fb225ebf9ac0c34f06b62a3a37817d13)" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="requested aes key for file 196438b4fb225ebf9ac0c34f06b62a3a37817d13, gid: 4DDyybdhC9su038YIG6JDj" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="fetched first chunk of 24, total size is 12472518 bytes" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:21 volumio go-librespot[1101]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:4DDyybdhC9su038YIG6JDj): failed setting stream for spotify:track:4DDyybdhC9su038YIG6JDj: ALSA error at snd_pcm_open: No such device" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:21 volumio go-librespot[1101]: time="2026-03-27T21:56:21+02:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:4DDyybdhC9su038YIG6JDj" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=debug msg="handling skip_next player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=trace msg="emitting websocket event: will_play" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=debug msg="selected format OGG_VORBIS_320 (ae9a3dd1a3cd5a7a4797e81dd8cf3db019a2ffa5)" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=debug msg="requested aes key for file ae9a3dd1a3cd5a7a4797e81dd8cf3db019a2ffa5, gid: 4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=debug msg="fetched first chunk of 14, total size is 6947468 bytes" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:22 volumio go-librespot[1101]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:4cIPLtg1avt2Jm3ne9S1zy): failed setting stream for spotify:track:4cIPLtg1avt2Jm3ne9S1zy: ALSA error at snd_pcm_open: No such device" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:22 volumio go-librespot[1101]: time="2026-03-27T21:56:22+02:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4cIPLtg1avt2Jm3ne9S1zy" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=debug msg="handling skip_next player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0U0ldCRmgCqhVvD6ksG63j" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=trace msg="emitting websocket event: will_play" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=debug msg="selected format OGG_VORBIS_320 (189758ad510776f44d92e391c3d0afc0f0819397)" uri="spotify:track:0U0ldCRmgCqhVvD6ksG63j" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=debug msg="requested aes key for file 189758ad510776f44d92e391c3d0afc0f0819397, gid: 0U0ldCRmgCqhVvD6ksG63j" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0U0ldCRmgCqhVvD6ksG63j" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=debug msg="fetched first chunk of 21, total size is 10836612 bytes" uri="spotify:track:0U0ldCRmgCqhVvD6ksG63j" Mar 27 21:56:23 volumio go-librespot[1101]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:0U0ldCRmgCqhVvD6ksG63j): failed setting stream for spotify:track:0U0ldCRmgCqhVvD6ksG63j: ALSA error at snd_pcm_open: No such device" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:0U0ldCRmgCqhVvD6ksG63j" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:0U0ldCRmgCqhVvD6ksG63j" Mar 27 21:56:23 volumio go-librespot[1101]: time="2026-03-27T21:56:23+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:0U0ldCRmgCqhVvD6ksG63j" Mar 27 21:56:27 volumio go-librespot[1101]: time="2026-03-27T21:56:27+02:00" level=debug msg="handling pause player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:27 volumio go-librespot[1101]: time="2026-03-27T21:56:27+02:00" level=debug msg="pause track at 0ms" Mar 27 21:56:27 volumio go-librespot[1101]: time="2026-03-27T21:56:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:27 volumio go-librespot[1101]: time="2026-03-27T21:56:27+02:00" level=debug msg="sending successful reply for dealer request" Mar 27 21:56:27 volumio go-librespot[1101]: time="2026-03-27T21:56:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 27 21:56:27 volumio go-librespot[1101]: time="2026-03-27T21:56:27+02:00" level=trace msg="emitting websocket event: paused" Mar 27 21:56:27 volumio volumio[840]: info: CoreCommandRouter::servicePushState Mar 27 21:56:27 volumio volumio[840]: info: CoreStateMachine::pushState Mar 27 21:56:27 volumio volumio[840]: info: CoreCommandRouter::volumioPushState Mar 27 21:56:31 volumio go-librespot[1101]: time="2026-03-27T21:56:31+02:00" level=trace msg="sent dealer ping" Mar 27 21:56:31 volumio go-librespot[1101]: time="2026-03-27T21:56:31+02:00" level=trace msg="received dealer pong" Mar 27 21:56:32 volumio go-librespot[1101]: time="2026-03-27T21:56:32+02:00" level=debug msg="handling resume player command from 138eb716e4469d5606930bb8ca79854e69ce5f0c" Mar 27 21:56:32 volumio go-librespot[1101]: time="2026-03-27T21:56:32+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0U0ldCRmgCqhVvD6ksG63j" Mar 27 21:56:32 volumio go-librespot[1101]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 27 21:56:32 volumio go-librespot[1101]: time="2026-03-27T21:56:32+02:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such device" Mar 27 21:56:43 volumio volumio[840]: info: CoreCommandRouter::volumioPlay Mar 27 21:56:43 volumio volumio[840]: info: CoreStateMachine::play index undefined Mar 27 21:56:43 volumio volumio[840]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 21:56:43 volumio volumio[840]: info: CorePlayQueue::getTrack 0 Mar 27 21:56:43 volumio volumio[840]: info: CoreStateMachine::startPlaybackTimer Mar 27 21:56:43 volumio volumio[840]: info: CorePlayQueue::getTrack 0 Mar 27 21:56:43 volumio volumio[840]: verbose: ControllerMpd::sendMpdCommand play Mar 27 21:56:43 volumio volumio[840]: info: sendMpdCommand play took 1 milliseconds Mar 27 21:56:43 volumio volumio[840]: info: CoreCommandRouter::servicePushState Mar 27 21:56:43 volumio volumio[840]: info: CorePlayQueue::getTrack 0 Mar 27 21:56:43 volumio volumio[840]: verbose: STATE SERVICE {"status":"play"} Mar 27 21:56:43 volumio volumio[840]: verbose: CURRENT POSITION 0 Mar 27 21:56:43 volumio volumio[840]: info: CoreStateMachine::syncState stateService play Mar 27 21:56:43 volumio volumio[840]: info: CoreStateMachine::syncState currentStatus pause Mar 27 21:56:43 volumio volumio[840]: info: CoreStateMachine::pushState Mar 27 21:56:43 volumio volumio[840]: info: CorePlayQueue::getTrack 0 Mar 27 21:56:43 volumio volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 21:56:43 volumio volumio[840]: info: CoreCommandRouter::volumioPushState Mar 27 21:56:43 volumio volumio[840]: info: [1774641403470] [MotherEarth] Error: connect ECONNREFUSED 127.0.0.1:443 Mar 27 21:56:43 volumio volumio[840]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 21:56:43 volumio volumio[840]: TypeError: Cannot read property 'toUpperCase' of undefined Mar 27 21:56:43 volumio volumio[840]: at motherearthradio.errorToast (/data/plugins/music_service/motherearthradio/index.js:423:41) Mar 27 21:56:43 volumio volumio[840]: at ClientRequest. (/data/plugins/music_service/motherearthradio/index.js:395:14) Mar 27 21:56:43 volumio volumio[840]: at ClientRequest.emit (events.js:315:20) Mar 27 21:56:43 volumio volumio[840]: at TLSSocket.socketErrorListener (_http_client.js:469:9) Mar 27 21:56:43 volumio volumio[840]: at TLSSocket.emit (events.js:315:20) Mar 27 21:56:43 volumio volumio[840]: at emitErrorNT (internal/streams/destroy.js:106:8) Mar 27 21:56:43 volumio volumio[840]: at emitErrorCloseNT (internal/streams/destroy.js:74:3) Mar 27 21:56:43 volumio volumio[840]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Mar 27 21:56:43 volumio volumio[840]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 21:56:43 volumio sudo[6071]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-03-27 21:55 Mar 27 21:56:43 volumio sudo[6071]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5d50cd80bebce60dddccd7f5e813d656e28ca4cd" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="7840f283c310c38bfe939a4c485727a6ff6a0ce1" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 21 Oct 2025 03:46:47 PM CEST" VOLUMIO_VERSION="3.866" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8e2f3a8aca3147ba51b5da8167dd6ff8"