-- Logs begin at Sat 2024-10-05 08:52:10 HKT, end at Sat 2024-10-05 09:24:39 HKT. -- Oct 05 09:23:08 volumio sudo[2057]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 05 09:23:08 volumio sudo[2057]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:23:08 volumio sudo[2057]: pam_unix(sudo:session): session closed for user root Oct 05 09:23:08 volumio sudo[2060]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 05 09:23:08 volumio sudo[2060]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:23:08 volumio sudo[2060]: pam_unix(sudo:session): session closed for user root Oct 05 09:23:08 volumio volumio[1153]: verbose: New Socket.io Connection to 192.168.68.56 from 192.168.68.55 UA: Mozilla/5.0 (Linux; Android 13; 23013PC75G Build/TKQ1.220905.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/129.0.6668.81 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Oct 05 09:23:08 volumio sudo[2063]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 05 09:23:08 volumio sudo[2063]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:23:08 volumio sudo[2063]: pam_unix(sudo:session): session closed for user root Oct 05 09:23:08 volumio sudo[2066]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 05 09:23:08 volumio sudo[2066]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:23:08 volumio sudo[2066]: pam_unix(sudo:session): session closed for user root Oct 05 09:23:08 volumio volumio[1153]: verbose: New Socket.io Connection to 192.168.68.56 from 192.168.68.55 UA: Mozilla/5.0 (Linux; Android 13; 23013PC75G Build/TKQ1.220905.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/129.0.6668.81 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::volumioGetQueue Oct 05 09:23:09 volumio volumio[1153]: info: CoreStateMachine::getQueue Oct 05 09:23:09 volumio volumio[1153]: info: CorePlayQueue::getQueue Oct 05 09:23:09 volumio volumio[1153]: info: Listing playlists Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 05 09:23:09 volumio volumio[1153]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Oct 05 09:23:09 volumio volumio[1153]: info: Received Get System Info Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:09 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 05 09:23:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 05 09:23:10 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 05 09:23:10 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 05 09:23:10 volumio volumio[1153]: info: Received Get System Info Oct 05 09:23:10 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:10 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:10 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:10 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:10 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:11 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 05 09:23:11 volumio volumio[1153]: info: Received Get System Info Oct 05 09:23:11 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:11 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:11 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:11 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:11 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:12 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:12 volumio volumio[1153]: info: Preloading song: spotify:track:5bcbAT32LJS87hklgOxUqM Oct 05 09:23:12 volumio volumio[1153]: info: Preloading song: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:12 volumio volumio[1153]: info: Preloading song: spotify:track:0aPt4Ye8V3tvvcIE7HurLk Oct 05 09:23:12 volumio volumio[1153]: info: Preloading song: spotify:track:7CEV16wtXaInlI8YN3jxro Oct 05 09:23:12 volumio volumio[1153]: info: Exploding uri spotify:track:5bcbAT32LJS87hklgOxUqM in service spop Oct 05 09:23:12 volumio volumio[1153]: SPOTIFY: EXPLODING URI:spotify:track:5bcbAT32LJS87hklgOxUqM Oct 05 09:23:12 volumio volumio[1153]: info: Exploding uri spotify:track:0BAwdYKY37wiZCYsBC252g in service spop Oct 05 09:23:12 volumio volumio[1153]: SPOTIFY: EXPLODING URI:spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:12 volumio volumio[1153]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5bcbAT32LJS87hklgOxUqM","service":"spop","name":"明天會更好","artist":"Tsai Chin","album":"明天會更好","type":"song","duration":320,"albumart":"https://i.scdn.co/image/ab67616d0000b273dc2c10bb91230309ec6b1d53","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 05 09:23:12 volumio volumio[1153]: info: Exploding uri spotify:track:0aPt4Ye8V3tvvcIE7HurLk in service spop Oct 05 09:23:12 volumio volumio[1153]: SPOTIFY: EXPLODING URI:spotify:track:0aPt4Ye8V3tvvcIE7HurLk Oct 05 09:23:12 volumio volumio[1153]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","service":"spop","name":"恰似你的溫柔","artist":"Teresa Teng","album":"寶麗金88極品音色系列 - 鄧麗君","type":"song","duration":262,"albumart":"https://i.scdn.co/image/ab67616d0000b27389f791e30fd53283f25d1fa6","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 05 09:23:12 volumio volumio[1153]: info: Exploding uri spotify:track:7CEV16wtXaInlI8YN3jxro in service spop Oct 05 09:23:12 volumio volumio[1153]: SPOTIFY: EXPLODING URI:spotify:track:7CEV16wtXaInlI8YN3jxro Oct 05 09:23:12 volumio volumio[1153]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0aPt4Ye8V3tvvcIE7HurLk","service":"spop","name":"那麼愛你為什麼","artist":"黃品源","album":"狠不下心","type":"song","duration":264,"albumart":"https://i.scdn.co/image/ab67616d0000b27389ee5e1bb0acff638577f96d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 05 09:23:12 volumio volumio[1153]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7CEV16wtXaInlI8YN3jxro","service":"spop","name":"我曾用心爱着你","artist":"Pan Mei Chen","album":"那些年那些歌 - 潘美辰","type":"song","duration":278,"albumart":"https://i.scdn.co/image/ab67616d0000b273268538baf7c64920e8a9fdf4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 05 09:23:13 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:13 volumio volumio[1153]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::ClearQueue Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:13 volumio volumio[1153]: info: CorePlayQueue::clearPlayQueue Oct 05 09:23:13 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:13 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::addQueueItems Oct 05 09:23:13 volumio volumio[1153]: info: CorePlayQueue::addQueueItems Oct 05 09:23:13 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:13 volumio volumio[1153]: info: Adding Item to queue: spotify:track:5bcbAT32LJS87hklgOxUqM Oct 05 09:23:13 volumio volumio[1153]: info: Using cached record of: spotify:track:5bcbAT32LJS87hklgOxUqM Oct 05 09:23:13 volumio volumio[1153]: info: Adding Item to queue: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:13 volumio volumio[1153]: info: Using cached record of: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:13 volumio volumio[1153]: info: Adding Item to queue: spotify:track:0aPt4Ye8V3tvvcIE7HurLk Oct 05 09:23:13 volumio volumio[1153]: info: Using cached record of: spotify:track:0aPt4Ye8V3tvvcIE7HurLk Oct 05 09:23:13 volumio volumio[1153]: info: Adding Item to queue: spotify:track:7CEV16wtXaInlI8YN3jxro Oct 05 09:23:13 volumio volumio[1153]: info: Using cached record of: spotify:track:7CEV16wtXaInlI8YN3jxro Oct 05 09:23:13 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:13 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::updateTrackBlock Oct 05 09:23:13 volumio volumio[1153]: info: CorePlayQueue::getTrackBlock Oct 05 09:23:13 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::play index 1 Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:13 volumio volumio[1153]: info: CorePlayQueue::getTrack 1 Oct 05 09:23:13 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:13 volumio volumio[1153]: info: CorePlayQueue::getTrack 1 Oct 05 09:23:13 volumio volumio[1153]: info: [1728091393091] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:13 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:13 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1471" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:13 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:13 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:13 volumio go-librespot[1375]: time="2024-10-05T09:23:13+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:14 volumio volumio[1153]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::ClearQueue Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:14 volumio volumio[1153]: info: CorePlayQueue::clearPlayQueue Oct 05 09:23:14 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:14 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::addQueueItems Oct 05 09:23:14 volumio volumio[1153]: info: CorePlayQueue::addQueueItems Oct 05 09:23:14 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:14 volumio volumio[1153]: info: Adding Item to queue: spotify:track:5bcbAT32LJS87hklgOxUqM Oct 05 09:23:14 volumio volumio[1153]: info: Using cached record of: spotify:track:5bcbAT32LJS87hklgOxUqM Oct 05 09:23:14 volumio volumio[1153]: info: Adding Item to queue: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:14 volumio volumio[1153]: info: Using cached record of: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:14 volumio volumio[1153]: info: Adding Item to queue: spotify:track:0aPt4Ye8V3tvvcIE7HurLk Oct 05 09:23:14 volumio volumio[1153]: info: Using cached record of: spotify:track:0aPt4Ye8V3tvvcIE7HurLk Oct 05 09:23:14 volumio volumio[1153]: info: Adding Item to queue: spotify:track:7CEV16wtXaInlI8YN3jxro Oct 05 09:23:14 volumio volumio[1153]: info: Using cached record of: spotify:track:7CEV16wtXaInlI8YN3jxro Oct 05 09:23:14 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:14 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::updateTrackBlock Oct 05 09:23:14 volumio volumio[1153]: info: CorePlayQueue::getTrackBlock Oct 05 09:23:14 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::play index 1 Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:14 volumio volumio[1153]: info: CorePlayQueue::getTrack 1 Oct 05 09:23:14 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:14 volumio volumio[1153]: info: CorePlayQueue::getTrack 1 Oct 05 09:23:14 volumio volumio[1153]: info: [1728091394758] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:14 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:14 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:14 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:14 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:14 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:14 volumio volumio[1153]: info: CorePlayQueue::getTrack 1 Oct 05 09:23:14 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:14 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:14 volumio go-librespot[1375]: time="2024-10-05T09:23:14+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:16 volumio volumio[1153]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::ClearQueue Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:16 volumio volumio[1153]: info: CorePlayQueue::clearPlayQueue Oct 05 09:23:16 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:16 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::addQueueItems Oct 05 09:23:16 volumio volumio[1153]: info: CorePlayQueue::addQueueItems Oct 05 09:23:16 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:16 volumio volumio[1153]: info: Adding Item to queue: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:16 volumio volumio[1153]: info: Using cached record of: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:16 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:16 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::updateTrackBlock Oct 05 09:23:16 volumio volumio[1153]: info: CorePlayQueue::getTrackBlock Oct 05 09:23:16 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::play index 0 Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:16 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:16 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:16 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:16 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:16 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:16 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:16 volumio volumio[1153]: info: [1728091396365] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:16 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:16 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:16 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:16 volumio go-librespot[1375]: time="2024-10-05T09:23:16+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:18 volumio volumio[1153]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::ClearQueue Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:18 volumio volumio[1153]: info: CorePlayQueue::clearPlayQueue Oct 05 09:23:18 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:18 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::addQueueItems Oct 05 09:23:18 volumio volumio[1153]: info: CorePlayQueue::addQueueItems Oct 05 09:23:18 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:18 volumio volumio[1153]: info: Adding Item to queue: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:18 volumio volumio[1153]: info: Using cached record of: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:18 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:18 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::updateTrackBlock Oct 05 09:23:18 volumio volumio[1153]: info: CorePlayQueue::getTrackBlock Oct 05 09:23:18 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::play index 0 Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:18 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:18 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:18 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:18 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:18 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:18 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:18 volumio volumio[1153]: info: [1728091398022] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:18 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:18 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:18 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio go-librespot[1375]: time="2024-10-05T09:23:18+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:18 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 05 09:23:22 volumio volumio[1153]: verbose: New Socket.io Connection to 192.168.68.56 from 192.168.68.55 UA: Mozilla/5.0 (Linux; Android 13; 23013PC75G Build/TKQ1.220905.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/129.0.6668.81 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Oct 05 09:23:22 volumio volumio[1153]: info: Received Get System Info Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:22 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:22 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:22 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:22 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::volumioGetQueue Oct 05 09:23:22 volumio volumio[1153]: info: CoreStateMachine::getQueue Oct 05 09:23:22 volumio volumio[1153]: info: CorePlayQueue::getQueue Oct 05 09:23:22 volumio volumio[1153]: info: Listing playlists Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 05 09:23:22 volumio volumio[1153]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Oct 05 09:23:22 volumio volumio[1153]: info: Received Get System Info Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:22 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:22 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:22 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:22 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 05 09:23:25 volumio volumio[1153]: info: CoreCommandRouter::volumioNext Oct 05 09:23:25 volumio volumio[1153]: info: CoreStateMachine::next Oct 05 09:23:25 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:25 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:25 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:25 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:25 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:25 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:25 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:25 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:25 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:25 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:25 volumio volumio[1153]: info: [1728091405953] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:25 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:25 volumio volumio[1153]: info: CoreStateMachine::updateTrackBlock Oct 05 09:23:25 volumio volumio[1153]: info: CorePlayQueue::getTrackBlock Oct 05 09:23:25 volumio go-librespot[1375]: time="2024-10-05T09:23:25+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:25 volumio go-librespot[1375]: time="2024-10-05T09:23:25+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:25 volumio go-librespot[1375]: time="2024-10-05T09:23:25+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:26 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:26 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:26 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:26 volumio go-librespot[1375]: time="2024-10-05T09:23:26+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:27 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 05 09:23:27 volumio volumio[1153]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 05 09:23:27 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 05 09:23:27 volumio volumio[1153]: info: Received Get System Version Oct 05 09:23:27 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 05 09:23:27 volumio volumio[1153]: info: Received Get System Info Oct 05 09:23:27 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:27 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:27 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:27 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:27 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:27 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:32 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:32 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:32 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:32 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:32 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:32 volumio volumio[1153]: info: [1728091412082] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:32 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:32 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:32 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:32 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:32 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:32 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:32 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:32 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:32 volumio volumio[1153]: info: [1728091412421] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:32 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:32 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:32 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:32 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:32 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:32 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:32 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:32 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:32 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:32 volumio volumio[1153]: info: [1728091412603] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:32 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:32 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:32 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:32 volumio go-librespot[1375]: time="2024-10-05T09:23:32+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:33 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:33 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:33 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:33 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:33 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:33 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:33 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:33 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:33 volumio volumio[1153]: info: [1728091413115] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:33 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:33 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:33 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:33 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:33 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:33 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:33 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:33 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:33 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:33 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:33 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:33 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:33 volumio volumio[1153]: info: [1728091413312] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:33 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:33 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:33 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:33 volumio go-librespot[1375]: time="2024-10-05T09:23:33+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:36 volumio volumio[1153]: verbose: New Socket.io Connection to 192.168.68.56 from 192.168.68.55 UA: Mozilla/5.0 (Linux; Android 13; 23013PC75G Build/TKQ1.220905.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/129.0.6668.81 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Oct 05 09:23:36 volumio volumio[1153]: info: Received Get System Info Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:36 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:36 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:36 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:36 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::volumioGetQueue Oct 05 09:23:36 volumio volumio[1153]: info: CoreStateMachine::getQueue Oct 05 09:23:36 volumio volumio[1153]: info: CorePlayQueue::getQueue Oct 05 09:23:36 volumio volumio[1153]: info: Listing playlists Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 05 09:23:36 volumio volumio[1153]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Oct 05 09:23:36 volumio volumio[1153]: info: Received Get System Info Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:36 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:36 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:36 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 05 09:23:43 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:43 volumio volumio[1153]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::ClearQueue Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:43 volumio volumio[1153]: info: CorePlayQueue::clearPlayQueue Oct 05 09:23:43 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:43 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::addQueueItems Oct 05 09:23:43 volumio volumio[1153]: info: CorePlayQueue::addQueueItems Oct 05 09:23:43 volumio volumio[1153]: info: Preload queue cleared Oct 05 09:23:43 volumio volumio[1153]: info: Adding Item to queue: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:43 volumio volumio[1153]: info: Using cached record of: spotify:track:0BAwdYKY37wiZCYsBC252g Oct 05 09:23:43 volumio volumio[1153]: info: CoreCommandRouter::volumioPushQueue Oct 05 09:23:43 volumio volumio[1153]: info: CorePlayQueue::saveQueue Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::updateTrackBlock Oct 05 09:23:43 volumio volumio[1153]: info: CorePlayQueue::getTrackBlock Oct 05 09:23:43 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::play index 0 Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::stop Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:43 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:43 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:43 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:43 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:43 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:43 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:43 volumio volumio[1153]: info: [1728091423511] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:43 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:43 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:43 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:43 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:43 volumio go-librespot[1375]: time="2024-10-05T09:23:43+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:44 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:23:44 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:23:44 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:23:44 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:23:44 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:44 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:23:46 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 05 09:23:52 volumio ntpd[1180]: Soliciting pool server 2606:4700:f1::123 Oct 05 09:23:56 volumio volumio[1153]: info: CoreCommandRouter::volumioPlay Oct 05 09:23:56 volumio volumio[1153]: info: CoreStateMachine::play index undefined Oct 05 09:23:56 volumio volumio[1153]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 09:23:56 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:56 volumio volumio[1153]: info: CoreStateMachine::startPlaybackTimer Oct 05 09:23:56 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:23:56 volumio volumio[1153]: info: CoreCommandRouter::volumioGetVisibleSources Oct 05 09:23:56 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 05 09:23:56 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 05 09:23:56 volumio volumio[1153]: info: [1728091436885] ControllerSpotify::clearAddPlayTrack Oct 05 09:23:56 volumio volumio[1153]: info: Sending Spotify command with payload to local API: /player/play Oct 05 09:23:56 volumio go-librespot[1375]: time="2024-10-05T09:23:56+08:00" level=debug msg="resolved context of track" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:56 volumio go-librespot[1375]: time="2024-10-05T09:23:56+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:56 volumio go-librespot[1375]: time="2024-10-05T09:23:56+08:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:56 volumio go-librespot[1375]: time="2024-10-05T09:23:56+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 09:23:56 volumio go-librespot[1375]: time="2024-10-05T09:23:56+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 09:23:56 volumio volumio[1153]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","play_origin":"go-librespot"}} Oct 05 09:23:56 volumio go-librespot[1375]: time="2024-10-05T09:23:56+08:00" level=debug msg="selected format OGG_VORBIS_320 (bdf1d422bf80dd5ad253970b131853b77e1d1d50)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:56 volumio go-librespot[1375]: time="2024-10-05T09:23:56+08:00" level=debug msg="requested aes key for file bdf1d422bf80dd5ad253970b131853b77e1d1d50, gid: 0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:57 volumio go-librespot[1375]: time="2024-10-05T09:23:57+08:00" level=debug msg="fetched first chunk of 20, total size is 10194533 bytes" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:57 volumio go-librespot[1375]: time="2024-10-05T09:23:57+08:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:57 volumio go-librespot[1375]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Oct 05 09:23:57 volumio go-librespot[1375]: time="2024-10-05T09:23:57+08:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:0BAwdYKY37wiZCYsBC252g: ALSA error at snd_pcm_open: No such device" Oct 05 09:23:57 volumio volumio[1153]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 05 09:23:57 volumio go-librespot[1375]: time="2024-10-05T09:23:57+08:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:57 volumio go-librespot[1375]: time="2024-10-05T09:23:57+08:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:23:57 volumio go-librespot[1375]: time="2024-10-05T09:23:57+08:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:0BAwdYKY37wiZCYsBC252g" Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 09:24:02 volumio volumio[1153]: info: Retrieving Cloud Streaming UI Oct 05 09:24:02 volumio volumio[1153]: info: Getting Tidal Cloud Configuration Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 09:24:02 volumio volumio[1153]: info: Getting Qobuz Cloud Configuration Oct 05 09:24:02 volumio volumio[1153]: info: Asking plugin for UI Config Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 09:24:02 volumio volumio[1153]: info: Getting Spotify Cloud Configuration Oct 05 09:24:02 volumio volumio[1153]: info: Asking plugin for UI Config Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 09:24:02 volumio volumio[1153]: info: Saving Spotify Acccount Oct 05 09:24:02 volumio volumio[1153]: info: Got it Oct 05 09:24:02 volumio volumio[1153]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Oct 05 09:24:02 volumio volumio[1153]: info: Got Tidal Cloud Configuration Oct 05 09:24:02 volumio volumio[1153]: info: Got it Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::volumioGetBrowseSources Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::volumioGetBrowseSources Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::volumioGetBrowseSources Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 05 09:24:02 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Oct 05 09:24:06 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 05 09:24:10 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 05 09:24:14 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 05 09:24:14 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 09:24:14 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 09:24:14 volumio volumio[1153]: info: Discovery: Getting this device information Oct 05 09:24:14 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:24:14 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:24:14 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 09:24:19 volumio volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 09:24:19 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:19 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 05 09:24:19 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:19 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 05 09:24:19 volumio volumio[1153]: info: Getting Alsa Cards List without I2S DAC Oct 05 09:24:19 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:19 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Oct 05 09:24:19 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:19 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:20 volumio volumio[1153]: Invalid card number. Oct 05 09:24:20 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:20 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:20 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:20 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:20 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:20 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:20 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:20 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 05 09:24:20 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 05 09:24:35 volumio volumio[1153]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Oct 05 09:24:35 volumio volumio[1153]: info: Preparing to save Alsa Options, stopping services first Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::volumioGetState Oct 05 09:24:35 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::volumioPause Oct 05 09:24:35 volumio volumio[1153]: info: CoreStateMachine::pause Oct 05 09:24:35 volumio volumio[1153]: info: Saving Audio Output to: {"output_device":{"value":"0","label":"HDMI Out"},"i2s":true,"i2sid":{"value":"allo-boss-dac","label":"Allo BOSS"}} Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:35 volumio volumio[1153]: info: Enabling I2S DAC: Allo BOSS Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , enableI2SDAC Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:35 volumio sudo[2125]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Oct 05 09:24:35 volumio sudo[2125]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:24:35 volumio sudo[2125]: pam_unix(sudo:session): session closed for user root Oct 05 09:24:35 volumio volumio[1153]: info: No Overlays Loaded Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SAlsaName Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:35 volumio sudo[2129]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay allo-boss-dac-pcm512x-audio Oct 05 09:24:35 volumio sudo[2129]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:24:35 volumio sudo[2129]: pam_unix(sudo:session): session closed for user root Oct 05 09:24:35 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:35 volumio volumio[1153]: warn: Unable to locate the device HDMI Out a reboot may be required. Oct 05 09:24:35 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SMixer Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:35 volumio volumio[1153]: info: Found match in i2s Card Database: setting mixer Digital for card Allo BOSS Oct 05 09:24:35 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::volumioUpdateVolumeSettings Oct 05 09:24:35 volumio volumio[1153]: info: Updating Volume Controller Parameters: Device: 2 Name: Allo BOSS Mixer: Digital Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Oct 05 09:24:35 volumio volumio[1153]: info: Disabling external Volume Control Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 09:24:35 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: wizard , setWizardAction Oct 05 09:24:35 volumio volumio[1153]: info: Preparing to generate the ALSA configuration file Oct 05 09:24:36 volumio volumio[1153]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: Invalid card number. Oct 05 09:24:36 volumio volumio[1153]: error: Cannot enable I2S Param: Error: Command failed: /usr/bin/sudo /usr/bin/dtoverlay allo-boss-dac-pcm512x-audio Oct 05 09:24:36 volumio volumio[1153]: * Failed to apply overlay '0_allo-boss-dac-pcm512x-audio' (kernel) Oct 05 09:24:36 volumio volumio[1153]: info: VolumeController:: Volume=undefined Mute =false Oct 05 09:24:36 volumio volumio[1153]: info: CoreStateMachine::pushState Oct 05 09:24:36 volumio volumio[1153]: info: CorePlayQueue::getTrack 0 Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::volumioPushState Oct 05 09:24:36 volumio volumio[1153]: info: MRS: Pushing multiroomSync output update for this device Oct 05 09:24:36 volumio volumio[1153]: info: MRS: Pushing multiroomSync output Oct 05 09:24:36 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 05 09:24:36 volumio volumio[1153]: info: Getting Alsa Cards List without I2S DAC Oct 05 09:24:36 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:36 volumio volumio[1153]: Invalid card number. Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 05 09:24:36 volumio volumio[1153]: info: ONKYO-CONTROL: New state: {"status":"stop","position":0,"title":"恰似你的溫柔","artist":"Teresa Teng","album":"寶麗金88極品音色系列 - 鄧麗君","albumart":"https://i.scdn.co/image/ab67616d0000b27389f791e30fd53283f25d1fa6","uri":"spotify:track:0BAwdYKY37wiZCYsBC252g","trackType":"spotify","codec":"ogg","seek":39116,"duration":262,"samplerate":"320 kbps","bitdepth":"16 bit","random":true,"repeat":true,"repeatSingle":false,"consume":false,"volume":81,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","updatedb":false,"volatile":false,"service":"spop"} connection: {"reconnect":true,"verify_commands":false,"port":60128,"host":"192.168.68.54","model":"TX-RZ830"} Oct 05 09:24:36 volumio volumio[1153]: SPOTIFY: RECEIVED VOLUMIO VOLUME 81 Oct 05 09:24:36 volumio volumio[1153]: info: Asound.conf file unchanged, so no further update is needed Oct 05 09:24:36 volumio volumio[1153]: info: Output device has changed, restarting MPD Oct 05 09:24:36 volumio sudo[2154]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 05 09:24:36 volumio sudo[2154]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:24:36 volumio sudo[2154]: pam_unix(sudo:session): session closed for user root Oct 05 09:24:36 volumio volumio[1153]: info: Output device has changed, restarting Shairport Sync Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:36 volumio sudo[2157]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 05 09:24:36 volumio sudo[2157]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:24:36 volumio systemd[1]: musicservicesshield.service: Succeeded. Oct 05 09:24:36 volumio systemd[1]: Stopped Shield Volumio Music Services in the User CPU Set. Oct 05 09:24:36 volumio systemd[1]: Stopping Shield Volumio Music Services in the User CPU Set... Oct 05 09:24:36 volumio systemd[1]: Stopping Music Player Daemon... Oct 05 09:24:36 volumio systemd[1]: mpd.service: Succeeded. Oct 05 09:24:36 volumio systemd[1]: Stopped Music Player Daemon. Oct 05 09:24:36 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:36 volumio volumio[1153]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 05 09:24:36 volumio volumio[1153]: xcb_connection_has_error() returned true Oct 05 09:24:36 volumio volumio[1153]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio vtcs[1920]: [2024-10-05 09:24:36.417] [tisoc] [warning] [SessionManagerImpl.cpp:243] Illegal State: IDLE Oct 05 09:24:36 volumio vtcs[1920]: [2024-10-05 09:24:36.418] [tisoc] [error] [SpkconServer.cpp:381] recv error. client fd=8 errorno=104 error=Connection reset by peer Oct 05 09:24:36 volumio vtcs[1920]: [2024-10-05 09:24:36.418] [tisoc] [error] [SpkconServer.cpp:376] recv error. socket disconnected Oct 05 09:24:36 volumio systemd[1]: Starting Music Player Daemon... Oct 05 09:24:36 volumio sudo[2166]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 05 09:24:36 volumio sudo[2166]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:24:36 volumio systemd[1]: Stopping Volumio Tidal Connect Service... Oct 05 09:24:36 volumio systemd[1]: vtcs.service: Main process exited, code=killed, status=15/TERM Oct 05 09:24:36 volumio systemd[1]: vtcs.service: Succeeded. Oct 05 09:24:36 volumio systemd[1]: Stopped Volumio Tidal Connect Service. Oct 05 09:24:36 volumio sudo[2166]: pam_unix(sudo:session): session closed for user root Oct 05 09:24:36 volumio volumio[1153]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 05 09:24:36 volumio volumio[1153]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Oct 05 09:24:36 volumio volumio[1153]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Oct 05 09:24:36 volumio volumio[1153]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 05 09:24:36 volumio sudo[2171]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Oct 05 09:24:36 volumio sudo[2171]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:24:36 volumio sudo[2162]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 05 09:24:36 volumio sudo[2162]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:24:36 volumio volumio[1153]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read property 'split' of undefined Oct 05 09:24:36 volumio volumio[1153]: info: MPD Permissions set Oct 05 09:24:36 volumio sudo[2171]: pam_unix(sudo:session): session closed for user root Oct 05 09:24:36 volumio sudo[2162]: pam_unix(sudo:session): session closed for user root Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 09:24:36 volumio volumio[1153]: info: Starting Shairport Sync Oct 05 09:24:36 volumio sudo[2182]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 05 09:24:36 volumio sudo[2182]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 09:24:36 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 05 09:24:36 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 05 09:24:36 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 05 09:24:36 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 05 09:24:36 volumio sudo[2182]: pam_unix(sudo:session): session closed for user root Oct 05 09:24:36 volumio volumio[1153]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 05 09:24:36 volumio volumio[1153]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Oct 05 09:24:36 volumio volumio[1153]: info: Shairport-Sync Started Oct 05 09:24:37 volumio mpd[2176]: Oct 05 09:24 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 05 09:24:37 volumio systemd[1]: Started Music Player Daemon. Oct 05 09:24:37 volumio sudo[2157]: pam_unix(sudo:session): session closed for user root Oct 05 09:24:37 volumio volumio[1153]: error: updateQueue error: null Oct 05 09:24:37 volumio systemd[1]: Starting Shield Volumio Music Services in the User CPU Set... Oct 05 09:24:37 volumio volumio[1153]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 05 09:24:37 volumio volumio[2189]: cset: --> shielding system active with Oct 05 09:24:37 volumio volumio[2189]: cset: "system" cpuset of CPUSPEC(1-3) with 136 tasks running Oct 05 09:24:37 volumio volumio[2189]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Oct 05 09:24:37 volumio systemd[1]: Started Shield Volumio Music Services in the User CPU Set. Oct 05 09:24:39 volumio volumio[1153]: info: ___________ PLUGINS: Run onVolumioReboot Tasks ___________ Oct 05 09:24:39 volumio volumio[1153]: info: PLUGIN onReboot : networkfs Oct 05 09:24:39 volumio volumio[1153]: info: PLUGIN onReboot : audiophonicsonoff Oct 05 09:24:39 volumio volumio[1153]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 05 09:24:39 volumio volumio[1153]: TypeError: Cannot read property 'writeSync' of undefined Oct 05 09:24:39 volumio volumio[1153]: at ControllerAudiophonicsOnOff.onVolumioReboot (/data/plugins/system_controller/audiophonicsonoff/index.js:35:25) Oct 05 09:24:39 volumio volumio[1153]: at PluginManager.onVolumioRebootPlugin (/volumio/app/pluginmanager.js:684:30) Oct 05 09:24:39 volumio volumio[1153]: at HashMap. (/volumio/app/pluginmanager.js:668:31) Oct 05 09:24:39 volumio volumio[1153]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Oct 05 09:24:39 volumio volumio[1153]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Oct 05 09:24:39 volumio volumio[1153]: at PluginManager.onVolumioReboot (/volumio/app/pluginmanager.js:666:20) Oct 05 09:24:39 volumio volumio[1153]: at CoreCommandRouter.reboot (/volumio/app/index.js:1331:22) Oct 05 09:24:39 volumio volumio[1153]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:864:33) Oct 05 09:24:39 volumio volumio[1153]: at Socket.emit (events.js:315:20) Oct 05 09:24:39 volumio volumio[1153]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 05 09:24:39 volumio volumio[1153]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Oct 05 09:24:39 volumio volumio[1153]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 05 09:24:39 volumio sudo[2213]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-05 09:23 Oct 05 09:24:39 volumio sudo[2213]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"