-- Logs begin at Sun 2024-09-29 12:50:45 CEST, end at Wed 2024-10-23 17:38:07 CEST. -- Oct 23 17:37:03 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 17:37:03 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 17:37:03 volumio volumio[1063]: info: Discovery: Getting this device information Oct 23 17:37:03 volumio volumio[1063]: info: CoreCommandRouter::volumioGetState Oct 23 17:37:03 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:03 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 17:37:22 volumio volumio[1063]: info: Preload queue cleared Oct 23 17:37:22 volumio volumio[1063]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::ClearQueue Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::stop Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:22 volumio volumio[1063]: info: CorePlayQueue::clearPlayQueue Oct 23 17:37:22 volumio volumio[1063]: info: CorePlayQueue::saveQueue Oct 23 17:37:22 volumio volumio[1063]: info: CoreCommandRouter::volumioPushQueue Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::addQueueItems Oct 23 17:37:22 volumio volumio[1063]: info: CorePlayQueue::addQueueItems Oct 23 17:37:22 volumio volumio[1063]: info: Preload queue cleared Oct 23 17:37:22 volumio volumio[1063]: info: Adding Item to queue: spotify:album:4iBu85RXwpJbpNLa8SMqrx Oct 23 17:37:22 volumio volumio[1063]: info: Using cached record of: spotify:album:4iBu85RXwpJbpNLa8SMqrx Oct 23 17:37:22 volumio volumio[1063]: info: CoreCommandRouter::volumioPushQueue Oct 23 17:37:22 volumio volumio[1063]: info: CorePlayQueue::saveQueue Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::updateTrackBlock Oct 23 17:37:22 volumio volumio[1063]: info: CorePlayQueue::getTrackBlock Oct 23 17:37:22 volumio volumio[1063]: info: CoreCommandRouter::volumioPlay Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::play index 0 Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::stop Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::play index undefined Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:22 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:22 volumio volumio[1063]: info: CoreStateMachine::startPlaybackTimer Oct 23 17:37:22 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:22 volumio volumio[1063]: info: [1729697842769] ControllerSpotify::clearAddPlayTrack Oct 23 17:37:22 volumio volumio[1063]: info: Sending Spotify command with payload to local API: /player/play Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=debug msg="resolved context of track" uri="spotify:track:6PQ4LvywnlGR86T4HHO17e" Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6PQ4LvywnlGR86T4HHO17e" Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6PQ4LvywnlGR86T4HHO17e" Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=trace msg="emitting websocket event: will_play" Oct 23 17:37:22 volumio volumio[1063]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6PQ4LvywnlGR86T4HHO17e","play_origin":"go-librespot"}} Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=debug msg="selected format OGG_VORBIS_320 (54bc9229469e7c624b5ea7f32a9a89214405d355)" uri="spotify:track:6PQ4LvywnlGR86T4HHO17e" Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=debug msg="requested aes key for file 54bc9229469e7c624b5ea7f32a9a89214405d355, gid: 6PQ4LvywnlGR86T4HHO17e" Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1290" Oct 23 17:37:22 volumio go-librespot[3300]: time="2024-10-23T17:37:22+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 23 17:37:23 volumio go-librespot[3300]: time="2024-10-23T17:37:23+02:00" level=debug msg="fetched first chunk of 16, total size is 7889260 bytes" uri="spotify:track:6PQ4LvywnlGR86T4HHO17e" Oct 23 17:37:23 volumio go-librespot[3300]: time="2024-10-23T17:37:23+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:6PQ4LvywnlGR86T4HHO17e" Oct 23 17:37:23 volumio go-librespot[3300]: time="2024-10-23T17:37:23+02:00" level=debug msg="created new output device" Oct 23 17:37:23 volumio go-librespot[3300]: time="2024-10-23T17:37:23+02:00" level=info msg="loaded track \"Genesis Hall\" (paused: false, position: 0ms, duration: 215106ms, prefetched: false)" uri="spotify:track:6PQ4LvywnlGR86T4HHO17e" Oct 23 17:37:23 volumio go-librespot[3300]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Oct 23 17:37:23 volumio go-librespot[3300]: Aborted Oct 23 17:37:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Oct 23 17:37:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 17:37:23 volumio volumio[1063]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Oct 23 17:37:23 volumio volumio[1063]: info: Connection to go-librespot Websocket closed Oct 23 17:37:26 volumio volumio[1063]: info: Initializing connection to go-librespot Websocket Oct 23 17:37:26 volumio volumio[1063]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 17:37:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 23 17:37:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Oct 23 17:37:26 volumio systemd[1]: Stopped go-librespot Daemon. Oct 23 17:37:26 volumio systemd[1]: Started go-librespot Daemon. Oct 23 17:37:26 volumio go-librespot[3357]: Librespot-go daemon starting... Oct 23 17:37:26 volumio go-librespot[3357]: time="2024-10-23T17:37:26+02:00" level=info msg="generated new device id: bf5e8bc29b27ac05542d07c6ea3be49653d28136" Oct 23 17:37:26 volumio go-librespot[3357]: time="2024-10-23T17:37:26+02:00" level=debug msg="stored credentials found for ravfed" Oct 23 17:37:26 volumio go-librespot[3357]: time="2024-10-23T17:37:26+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 17:37:26 volumio go-librespot[3357]: time="2024-10-23T17:37:26+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 17:37:26 volumio go-librespot[3357]: time="2024-10-23T17:37:26+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 17:37:26 volumio go-librespot[3357]: time="2024-10-23T17:37:26+02:00" level=debug msg="zeroconf server listening on port 43178" Oct 23 17:37:26 volumio go-librespot[3357]: time="2024-10-23T17:37:26+02:00" level=debug msg="obtained new client token: AABqZk7OoE83jvKHP/efpISokkiPqkqYSVocZOleVw9u30nOkJdyiFxGE4VWGkM7vqltS0toBA49DE2SqPl32WW4RpbiV74+W8iXI7qSEvr0dpOZVOTmSbDzIMzB3SPJY9jsEp7PjfacyGiYXnimqvGmm+ynb0fbYVPkziwv4oPOhh625V6L9xw5GWfdEJmyv4L/2nu1p2v7b92qENq4X+RInXmG+NiAt4U8NCyODFH7YG56sPKyEEB99a4F8Q==" Oct 23 17:37:26 volumio go-librespot[3357]: time="2024-10-23T17:37:26+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Oct 23 17:37:26 volumio go-librespot[3357]: time="2024-10-23T17:37:26+02:00" level=debug msg="completed keyexchange" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="completed challenge" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="authenticated as ravfed" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="authenticated as ravfed" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="dealer connection opened" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="initializing zeroconf session, username: ravfed" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="autoplay enabled: false" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="received connection id: YjI3M2UwYzItYWFkMi00MWMwLTk1YzUtZGY2Y2MyMDNiZjYwK2RlYWxlcit0Y3A6Ly8wYWNhNTkxNS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQjdGMUVFQ0JFMEIzQjREQ0I4QzQyMEE4RjdCODdBMEY3REZGODMyNDZENDZFRURBRTlEM0I5MUIzOEFDOTc2Rg==" Oct 23 17:37:27 volumio go-librespot[3357]: time="2024-10-23T17:37:27+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 23 17:37:29 volumio volumio[1063]: info: Initializing connection to go-librespot Websocket Oct 23 17:37:29 volumio go-librespot[3357]: time="2024-10-23T17:37:29+02:00" level=debug msg="new websocket client" Oct 23 17:37:29 volumio volumio[1063]: info: Connection to go-librespot Websocket established Oct 23 17:37:32 volumio volumio[1063]: info: Getting Spotify volume Oct 23 17:37:32 volumio volumio[1063]: info: Spotify volume: 100 Oct 23 17:37:32 volumio volumio[1063]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Oct 23 17:37:32 volumio volumio[1063]: info: CoreCommandRouter::volumioGetState Oct 23 17:37:32 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:32 volumio volumio[1063]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Oct 23 17:37:32 volumio volumio[1063]: SPOTIFY: SPOTIFY VOLUME 100 Oct 23 17:37:32 volumio volumio[1063]: SPOTIFY: VOLUMIO VOLUME 61 Oct 23 17:37:32 volumio volumio[1063]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 23 17:37:32 volumio volumio[1063]: info: Setting Spotify Volume from Volumio: 61 Oct 23 17:37:33 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 17:37:33 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 17:37:33 volumio volumio[1063]: info: Discovery: Getting this device information Oct 23 17:37:33 volumio volumio[1063]: info: CoreCommandRouter::volumioGetState Oct 23 17:37:33 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:33 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 17:37:33 volumio volumio[1063]: SPOTIFY: SETTING SPOTIFY VOLUME 61 Oct 23 17:37:33 volumio volumio[1063]: info: Sending Spotify command with payload to local API: /player/volume Oct 23 17:37:33 volumio go-librespot[3357]: time="2024-10-23T17:37:33+02:00" level=debug msg="update volume to 39976/65535" Oct 23 17:37:33 volumio go-librespot[3357]: time="2024-10-23T17:37:33+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 23 17:37:33 volumio go-librespot[3357]: time="2024-10-23T17:37:33+02:00" level=trace msg="emitting websocket event: volume" Oct 23 17:37:33 volumio volumio[1063]: SPOTIFY: received: {"type":"volume","data":{"value":61,"max":100}} Oct 23 17:37:33 volumio volumio[1063]: SPOTIFY: RECEIVED SPOTIFY VOLUME 61 Oct 23 17:37:34 volumio volumio[1063]: info: Preload queue cleared Oct 23 17:37:34 volumio volumio[1063]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::ClearQueue Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::stop Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:34 volumio volumio[1063]: info: CorePlayQueue::clearPlayQueue Oct 23 17:37:34 volumio volumio[1063]: info: CorePlayQueue::saveQueue Oct 23 17:37:34 volumio volumio[1063]: info: CoreCommandRouter::volumioPushQueue Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::addQueueItems Oct 23 17:37:34 volumio volumio[1063]: info: CorePlayQueue::addQueueItems Oct 23 17:37:34 volumio volumio[1063]: info: Preload queue cleared Oct 23 17:37:34 volumio volumio[1063]: info: Adding Item to queue: spotify:track:6PQ4LvywnlGR86T4HHO17e Oct 23 17:37:34 volumio volumio[1063]: info: Using cached record of: spotify:track:6PQ4LvywnlGR86T4HHO17e Oct 23 17:37:34 volumio volumio[1063]: info: Adding Item to queue: spotify:track:5NB3W7bWcyorADuYDZ3osG Oct 23 17:37:34 volumio volumio[1063]: info: Using cached record of: spotify:track:5NB3W7bWcyorADuYDZ3osG Oct 23 17:37:34 volumio volumio[1063]: info: Adding Item to queue: spotify:track:66i8HD6kXenti31HXdXmDG Oct 23 17:37:34 volumio volumio[1063]: info: Using cached record of: spotify:track:66i8HD6kXenti31HXdXmDG Oct 23 17:37:34 volumio volumio[1063]: info: Adding Item to queue: spotify:track:5w5iVU4HJFqbjQmELVa2Bf Oct 23 17:37:34 volumio volumio[1063]: info: Using cached record of: spotify:track:5w5iVU4HJFqbjQmELVa2Bf Oct 23 17:37:34 volumio volumio[1063]: info: Adding Item to queue: spotify:track:1ShcFO2Qy8kmKgb0YNZGjY Oct 23 17:37:34 volumio volumio[1063]: info: Using cached record of: spotify:track:1ShcFO2Qy8kmKgb0YNZGjY Oct 23 17:37:34 volumio volumio[1063]: info: Adding Item to queue: spotify:track:3t5C5qQI3wqJasYIKOJEB7 Oct 23 17:37:34 volumio volumio[1063]: info: Using cached record of: spotify:track:3t5C5qQI3wqJasYIKOJEB7 Oct 23 17:37:34 volumio volumio[1063]: info: Adding Item to queue: spotify:track:6v2IJEjc46hgOOf9R5ah6x Oct 23 17:37:34 volumio volumio[1063]: info: Using cached record of: spotify:track:6v2IJEjc46hgOOf9R5ah6x Oct 23 17:37:34 volumio volumio[1063]: info: Adding Item to queue: spotify:track:3vcdI5tuRfMr7XvU8LbfKW Oct 23 17:37:34 volumio volumio[1063]: info: Using cached record of: spotify:track:3vcdI5tuRfMr7XvU8LbfKW Oct 23 17:37:34 volumio volumio[1063]: info: Adding Item to queue: spotify:track:6FSMkF5hweh2bFK3a2t5rF Oct 23 17:37:34 volumio volumio[1063]: info: Using cached record of: spotify:track:6FSMkF5hweh2bFK3a2t5rF Oct 23 17:37:34 volumio volumio[1063]: info: CoreCommandRouter::volumioPushQueue Oct 23 17:37:34 volumio volumio[1063]: info: CorePlayQueue::saveQueue Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::updateTrackBlock Oct 23 17:37:34 volumio volumio[1063]: info: CorePlayQueue::getTrackBlock Oct 23 17:37:34 volumio volumio[1063]: info: CoreCommandRouter::volumioPlay Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::play index 3 Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::stop Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::play index undefined Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:34 volumio volumio[1063]: info: CorePlayQueue::getTrack 3 Oct 23 17:37:34 volumio volumio[1063]: info: CoreStateMachine::startPlaybackTimer Oct 23 17:37:34 volumio volumio[1063]: info: CorePlayQueue::getTrack 3 Oct 23 17:37:34 volumio volumio[1063]: info: [1729697854641] ControllerSpotify::clearAddPlayTrack Oct 23 17:37:34 volumio volumio[1063]: info: Sending Spotify command with payload to local API: /player/play Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=debug msg="resolved context of track" uri="spotify:track:5w5iVU4HJFqbjQmELVa2Bf" Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5w5iVU4HJFqbjQmELVa2Bf" Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5w5iVU4HJFqbjQmELVa2Bf" Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=trace msg="emitting websocket event: will_play" Oct 23 17:37:34 volumio volumio[1063]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5w5iVU4HJFqbjQmELVa2Bf","play_origin":"go-librespot"}} Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=debug msg="selected format OGG_VORBIS_320 (b0e91f77ff40aa941d4b69aebf0e14a38005c08e)" uri="spotify:track:5w5iVU4HJFqbjQmELVa2Bf" Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=debug msg="requested aes key for file b0e91f77ff40aa941d4b69aebf0e14a38005c08e, gid: 5w5iVU4HJFqbjQmELVa2Bf" Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 23 17:37:34 volumio go-librespot[3357]: time="2024-10-23T17:37:34+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1290" Oct 23 17:37:35 volumio go-librespot[3357]: time="2024-10-23T17:37:35+02:00" level=debug msg="fetched first chunk of 49, total size is 25359860 bytes" uri="spotify:track:5w5iVU4HJFqbjQmELVa2Bf" Oct 23 17:37:35 volumio go-librespot[3357]: time="2024-10-23T17:37:35+02:00" level=trace msg="seek to 0ms (diff: -377ms, samples: 0, bytes: 11604)" uri="spotify:track:5w5iVU4HJFqbjQmELVa2Bf" Oct 23 17:37:35 volumio go-librespot[3357]: time="2024-10-23T17:37:35+02:00" level=debug msg="created new output device" Oct 23 17:37:35 volumio go-librespot[3357]: time="2024-10-23T17:37:35+02:00" level=info msg="loaded track \"A Sailor's Life\" (paused: false, position: 0ms, duration: 668360ms, prefetched: false)" uri="spotify:track:5w5iVU4HJFqbjQmELVa2Bf" Oct 23 17:37:35 volumio go-librespot[3357]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Oct 23 17:37:35 volumio volumio[1063]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Oct 23 17:37:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Oct 23 17:37:35 volumio go-librespot[3357]: Aborted Oct 23 17:37:35 volumio volumio[1063]: info: Connection to go-librespot Websocket closed Oct 23 17:37:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 17:37:36 volumio volumio[1063]: info: Preload queue cleared Oct 23 17:37:36 volumio volumio[1063]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::ClearQueue Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::stop Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:36 volumio volumio[1063]: info: CorePlayQueue::clearPlayQueue Oct 23 17:37:36 volumio volumio[1063]: info: CorePlayQueue::saveQueue Oct 23 17:37:36 volumio volumio[1063]: info: CoreCommandRouter::volumioPushQueue Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::addQueueItems Oct 23 17:37:36 volumio volumio[1063]: info: CorePlayQueue::addQueueItems Oct 23 17:37:36 volumio volumio[1063]: info: Preload queue cleared Oct 23 17:37:36 volumio volumio[1063]: info: Adding Item to queue: spotify:track:6PQ4LvywnlGR86T4HHO17e Oct 23 17:37:36 volumio volumio[1063]: info: Using cached record of: spotify:track:6PQ4LvywnlGR86T4HHO17e Oct 23 17:37:36 volumio volumio[1063]: info: Adding Item to queue: spotify:track:5NB3W7bWcyorADuYDZ3osG Oct 23 17:37:36 volumio volumio[1063]: info: Using cached record of: spotify:track:5NB3W7bWcyorADuYDZ3osG Oct 23 17:37:36 volumio volumio[1063]: info: Adding Item to queue: spotify:track:66i8HD6kXenti31HXdXmDG Oct 23 17:37:36 volumio volumio[1063]: info: Using cached record of: spotify:track:66i8HD6kXenti31HXdXmDG Oct 23 17:37:36 volumio volumio[1063]: info: Adding Item to queue: spotify:track:5w5iVU4HJFqbjQmELVa2Bf Oct 23 17:37:36 volumio volumio[1063]: info: Using cached record of: spotify:track:5w5iVU4HJFqbjQmELVa2Bf Oct 23 17:37:36 volumio volumio[1063]: info: Adding Item to queue: spotify:track:1ShcFO2Qy8kmKgb0YNZGjY Oct 23 17:37:36 volumio volumio[1063]: info: Using cached record of: spotify:track:1ShcFO2Qy8kmKgb0YNZGjY Oct 23 17:37:36 volumio volumio[1063]: info: Adding Item to queue: spotify:track:3t5C5qQI3wqJasYIKOJEB7 Oct 23 17:37:36 volumio volumio[1063]: info: Using cached record of: spotify:track:3t5C5qQI3wqJasYIKOJEB7 Oct 23 17:37:36 volumio volumio[1063]: info: Adding Item to queue: spotify:track:6v2IJEjc46hgOOf9R5ah6x Oct 23 17:37:36 volumio volumio[1063]: info: Using cached record of: spotify:track:6v2IJEjc46hgOOf9R5ah6x Oct 23 17:37:36 volumio volumio[1063]: info: Adding Item to queue: spotify:track:3vcdI5tuRfMr7XvU8LbfKW Oct 23 17:37:36 volumio volumio[1063]: info: Using cached record of: spotify:track:3vcdI5tuRfMr7XvU8LbfKW Oct 23 17:37:36 volumio volumio[1063]: info: Adding Item to queue: spotify:track:6FSMkF5hweh2bFK3a2t5rF Oct 23 17:37:36 volumio volumio[1063]: info: Using cached record of: spotify:track:6FSMkF5hweh2bFK3a2t5rF Oct 23 17:37:36 volumio volumio[1063]: info: CoreCommandRouter::volumioPushQueue Oct 23 17:37:36 volumio volumio[1063]: info: CorePlayQueue::saveQueue Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::updateTrackBlock Oct 23 17:37:36 volumio volumio[1063]: info: CorePlayQueue::getTrackBlock Oct 23 17:37:36 volumio volumio[1063]: info: CoreCommandRouter::volumioPlay Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::play index 3 Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::stop Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::play index undefined Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:36 volumio volumio[1063]: info: CorePlayQueue::getTrack 3 Oct 23 17:37:36 volumio volumio[1063]: info: CoreStateMachine::startPlaybackTimer Oct 23 17:37:36 volumio volumio[1063]: info: CorePlayQueue::getTrack 3 Oct 23 17:37:36 volumio volumio[1063]: info: [1729697856589] ControllerSpotify::clearAddPlayTrack Oct 23 17:37:36 volumio volumio[1063]: info: Sending Spotify command with payload to local API: /player/play Oct 23 17:37:36 volumio volumio[1063]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 17:37:38 volumio volumio[1063]: info: Initializing connection to go-librespot Websocket Oct 23 17:37:38 volumio volumio[1063]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 17:37:38 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 23 17:37:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Oct 23 17:37:38 volumio systemd[1]: Stopped go-librespot Daemon. Oct 23 17:37:38 volumio systemd[1]: Started go-librespot Daemon. Oct 23 17:37:38 volumio go-librespot[3369]: Librespot-go daemon starting... Oct 23 17:37:38 volumio go-librespot[3369]: time="2024-10-23T17:37:38+02:00" level=info msg="generated new device id: 9a2c153819da3195407e56ab4998aad894bd35ec" Oct 23 17:37:38 volumio go-librespot[3369]: time="2024-10-23T17:37:38+02:00" level=debug msg="stored credentials found for ravfed" Oct 23 17:37:38 volumio go-librespot[3369]: time="2024-10-23T17:37:38+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 17:37:38 volumio go-librespot[3369]: time="2024-10-23T17:37:38+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 17:37:38 volumio go-librespot[3369]: time="2024-10-23T17:37:38+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 17:37:38 volumio go-librespot[3369]: time="2024-10-23T17:37:38+02:00" level=debug msg="zeroconf server listening on port 38421" Oct 23 17:37:38 volumio go-librespot[3369]: time="2024-10-23T17:37:38+02:00" level=debug msg="obtained new client token: AADJl0JYg5yho3YlyMPwuOKz9ZRhaG4oUIRRyzWOLZWmnfBduRXTVh9hqJUbXjvlTIuzvoEBcCalKifln+2cq0oMBH+atPnY+13ZFYiRgeLYsv6Hku/3PEuyCBHPJORTPAhy3fauppUaguS4f8WwxyuWQStfA5/qUmjosu4UViJjGWvwYa6rKHzaK/h42yri6ECoUNKtgpJRZGDfZ01fbK3tEC+HqEmwNiRMHyviEb4au/+YJIx6un5u511Bjg==" Oct 23 17:37:38 volumio go-librespot[3369]: time="2024-10-23T17:37:38+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Oct 23 17:37:38 volumio go-librespot[3369]: time="2024-10-23T17:37:38+02:00" level=debug msg="completed keyexchange" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="completed challenge" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="authenticated as ravfed" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="authenticated as ravfed" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="dealer connection opened" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="initializing zeroconf session, username: ravfed" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="autoplay enabled: false" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="received connection id: YzkzOWFlMzAtMjQ1Ny00ZWVjLThkYTEtNWI2Nzc3YjgwMTExK2RlYWxlcit0Y3A6Ly8wYWNhNTkxYy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMkYzQkI3RTY3NDFBMTBBNEE4RDM0NTQ4QUI4REUzM0JCOTI0QkMzNTlFOTJGRURBRTg5NEFDRkYzQTZBRTMxNA==" Oct 23 17:37:39 volumio go-librespot[3369]: time="2024-10-23T17:37:39+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 23 17:37:41 volumio volumio[1063]: info: Initializing connection to go-librespot Websocket Oct 23 17:37:41 volumio go-librespot[3369]: time="2024-10-23T17:37:41+02:00" level=debug msg="new websocket client" Oct 23 17:37:41 volumio volumio[1063]: info: Connection to go-librespot Websocket established Oct 23 17:37:43 volumio volumio[1063]: info: Preload queue cleared Oct 23 17:37:43 volumio volumio[1063]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::ClearQueue Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::stop Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:43 volumio volumio[1063]: info: CorePlayQueue::clearPlayQueue Oct 23 17:37:43 volumio volumio[1063]: info: CorePlayQueue::saveQueue Oct 23 17:37:43 volumio volumio[1063]: info: CoreCommandRouter::volumioPushQueue Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::addQueueItems Oct 23 17:37:43 volumio volumio[1063]: info: CorePlayQueue::addQueueItems Oct 23 17:37:43 volumio volumio[1063]: info: Preload queue cleared Oct 23 17:37:43 volumio volumio[1063]: info: Adding Item to queue: spotify:track:66i8HD6kXenti31HXdXmDG Oct 23 17:37:43 volumio volumio[1063]: info: Using cached record of: spotify:track:66i8HD6kXenti31HXdXmDG Oct 23 17:37:43 volumio volumio[1063]: info: CoreCommandRouter::volumioPushQueue Oct 23 17:37:43 volumio volumio[1063]: info: CorePlayQueue::saveQueue Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::updateTrackBlock Oct 23 17:37:43 volumio volumio[1063]: info: CorePlayQueue::getTrackBlock Oct 23 17:37:43 volumio volumio[1063]: info: CoreCommandRouter::volumioPlay Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::play index 0 Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::stop Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::play index undefined Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:43 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:43 volumio volumio[1063]: info: CoreStateMachine::startPlaybackTimer Oct 23 17:37:43 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:43 volumio volumio[1063]: info: CoreCommandRouter::volumioGetVisibleSources Oct 23 17:37:43 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 17:37:43 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 23 17:37:43 volumio volumio[1063]: info: [1729697863178] ControllerSpotify::clearAddPlayTrack Oct 23 17:37:43 volumio volumio[1063]: info: Sending Spotify command with payload to local API: /player/play Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="resolved context of track" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=trace msg="emitting websocket event: will_play" Oct 23 17:37:43 volumio volumio[1063]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:66i8HD6kXenti31HXdXmDG","play_origin":"go-librespot"}} Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="selected format OGG_VORBIS_320 (74463280f67675c7b4a22dccca44977f976e6383)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="requested aes key for file 74463280f67675c7b4a22dccca44977f976e6383, gid: 66i8HD6kXenti31HXdXmDG" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1290" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="fetched first chunk of 18, total size is 9365132 bytes" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=debug msg="created new output device" Oct 23 17:37:43 volumio go-librespot[3369]: time="2024-10-23T17:37:43+02:00" level=info msg="loaded track \"Autopsy\" (paused: false, position: 0ms, duration: 260226ms, prefetched: false)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:43 volumio go-librespot[3369]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Oct 23 17:37:43 volumio go-librespot[3369]: Aborted Oct 23 17:37:43 volumio volumio[1063]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Oct 23 17:37:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Oct 23 17:37:43 volumio volumio[1063]: info: Connection to go-librespot Websocket closed Oct 23 17:37:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 17:37:44 volumio volumio[1063]: info: Getting Spotify volume Oct 23 17:37:44 volumio volumio[1063]: (node:1063) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 17:37:44 volumio volumio[1063]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 23 17:37:44 volumio volumio[1063]: (node:1063) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2) Oct 23 17:37:44 volumio volumio[1063]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Oct 23 17:37:44 volumio volumio[1063]: info: CoreCommandRouter::volumioGetState Oct 23 17:37:44 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:44 volumio volumio[1063]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Oct 23 17:37:45 volumio volumio[1063]: info: CoreCommandRouter::volumioPlay Oct 23 17:37:45 volumio volumio[1063]: info: CoreStateMachine::play index undefined Oct 23 17:37:45 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:45 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:45 volumio volumio[1063]: info: CoreStateMachine::startPlaybackTimer Oct 23 17:37:45 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:45 volumio volumio[1063]: info: CoreCommandRouter::volumioGetVisibleSources Oct 23 17:37:45 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 17:37:45 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 23 17:37:45 volumio volumio[1063]: info: [1729697865803] ControllerSpotify::clearAddPlayTrack Oct 23 17:37:45 volumio volumio[1063]: info: Sending Spotify command with payload to local API: /player/play Oct 23 17:37:45 volumio volumio[1063]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 17:37:46 volumio volumio[1063]: info: Initializing connection to go-librespot Websocket Oct 23 17:37:46 volumio volumio[1063]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 17:37:46 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 23 17:37:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Oct 23 17:37:46 volumio systemd[1]: Stopped go-librespot Daemon. Oct 23 17:37:46 volumio systemd[1]: Started go-librespot Daemon. Oct 23 17:37:46 volumio go-librespot[3380]: Librespot-go daemon starting... Oct 23 17:37:46 volumio go-librespot[3380]: time="2024-10-23T17:37:46+02:00" level=info msg="generated new device id: 872cd694986fab5b38a1bff6271fa0f5d5ed2074" Oct 23 17:37:46 volumio go-librespot[3380]: time="2024-10-23T17:37:46+02:00" level=debug msg="stored credentials found for ravfed" Oct 23 17:37:46 volumio go-librespot[3380]: time="2024-10-23T17:37:46+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 17:37:46 volumio go-librespot[3380]: time="2024-10-23T17:37:46+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 17:37:46 volumio go-librespot[3380]: time="2024-10-23T17:37:46+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 17:37:46 volumio go-librespot[3380]: time="2024-10-23T17:37:46+02:00" level=debug msg="zeroconf server listening on port 44085" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="obtained new client token: AAAqpzaC7Mgrh3UCyt4gbD1INk7rOVUUTXcG4B0yhl1ZoVaG9gUd8TnOpa/xJ4UH9PwybAU/CvafBkbp/LLT01+wE7Ws+nC/yhUZ/QxpH4M8EIcbdBlLx9Ow4ed8zpxY2kVR3ze82qwQVdfDjF9LXtU1+Z72BI5OKRunsVrZ2sHApYV7VyhkedFAWSXj+VKpTmXXtBDIjZeJ0GdLTQj9mvxCqC+ylhRmnggnBStEff8Y6NHzg47xym+lsWunjw==" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="completed keyexchange" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="completed challenge" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="authenticated as ravfed" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="authenticated as ravfed" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="dealer connection opened" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="initializing zeroconf session, username: ravfed" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="autoplay enabled: false" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="received connection id: ZmM0ZGQxOTctM2E2MC00NjA2LTkzNDMtYTQyYWYyMjVjNDU0K2RlYWxlcit0Y3A6Ly8wYWNhNTg4NS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArODg3NUM2RTBDRThCMTgxMUIxMzQ2QjIzMDIzMUIxM0I2RUU5RDJGM0QzN0M1Mjg5MTQzQ0YzNUQ0NTE0N0QyQg==" Oct 23 17:37:47 volumio go-librespot[3380]: time="2024-10-23T17:37:47+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 23 17:37:48 volumio volumio[1063]: info: CoreCommandRouter::volumioPlay Oct 23 17:37:48 volumio volumio[1063]: info: CoreStateMachine::play index undefined Oct 23 17:37:48 volumio volumio[1063]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 17:37:48 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:48 volumio volumio[1063]: info: CoreStateMachine::startPlaybackTimer Oct 23 17:37:48 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:48 volumio volumio[1063]: info: CoreCommandRouter::volumioGetVisibleSources Oct 23 17:37:48 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 23 17:37:48 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 23 17:37:48 volumio volumio[1063]: info: [1729697868235] ControllerSpotify::clearAddPlayTrack Oct 23 17:37:48 volumio volumio[1063]: info: Sending Spotify command with payload to local API: /player/play Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="resolved context of track" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=trace msg="emitting websocket event: will_play" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="selected format OGG_VORBIS_320 (74463280f67675c7b4a22dccca44977f976e6383)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="requested aes key for file 74463280f67675c7b4a22dccca44977f976e6383, gid: 66i8HD6kXenti31HXdXmDG" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1290" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="fetched first chunk of 18, total size is 9365132 bytes" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=debug msg="created new output device" Oct 23 17:37:48 volumio go-librespot[3380]: time="2024-10-23T17:37:48+02:00" level=info msg="loaded track \"Autopsy\" (paused: false, position: 1ms, duration: 260226ms, prefetched: false)" uri="spotify:track:66i8HD6kXenti31HXdXmDG" Oct 23 17:37:48 volumio go-librespot[3380]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Oct 23 17:37:48 volumio go-librespot[3380]: Aborted Oct 23 17:37:48 volumio volumio[1063]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Oct 23 17:37:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Oct 23 17:37:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 23 17:37:49 volumio volumio[1063]: info: Initializing connection to go-librespot Websocket Oct 23 17:37:49 volumio volumio[1063]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 23 17:37:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 23 17:37:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Oct 23 17:37:51 volumio systemd[1]: Stopped go-librespot Daemon. Oct 23 17:37:51 volumio systemd[1]: Started go-librespot Daemon. Oct 23 17:37:51 volumio go-librespot[3393]: Librespot-go daemon starting... Oct 23 17:37:51 volumio go-librespot[3393]: time="2024-10-23T17:37:51+02:00" level=info msg="generated new device id: 7d1cc6ea05f7beba6811550d55064d477945b294" Oct 23 17:37:51 volumio go-librespot[3393]: time="2024-10-23T17:37:51+02:00" level=debug msg="stored credentials found for ravfed" Oct 23 17:37:51 volumio go-librespot[3393]: time="2024-10-23T17:37:51+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 23 17:37:51 volumio go-librespot[3393]: time="2024-10-23T17:37:51+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 23 17:37:51 volumio go-librespot[3393]: time="2024-10-23T17:37:51+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 23 17:37:51 volumio go-librespot[3393]: time="2024-10-23T17:37:51+02:00" level=debug msg="zeroconf server listening on port 34206" Oct 23 17:37:51 volumio go-librespot[3393]: time="2024-10-23T17:37:51+02:00" level=debug msg="obtained new client token: AAB3wCg7DqtVNny2VBW5H8wW0M+LG8feIiRrF4YUJ+UK8yBP8PDVXA4F9SJe7xnLXhUGdwCskfAqcL14VNMzfxoo9wt+elh/+ntJCBPpJ0CAGiUrKjAmiSXkD+/dtM+FFqwtrlu+rxvspjZh+cnPr78N4fwD3f2VXL2wWFbEvMeqVGi0grMnLtR19snirkshpBaQwacjJ7L4EdJpKq+UMsLZMsfIbWB4MYbXNoVX+m7YfMIVThQ6b8m7bkW6cQ==" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="completed keyexchange" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="completed challenge" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="authenticated as ravfed" Oct 23 17:37:52 volumio volumio[1063]: info: Initializing connection to go-librespot Websocket Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="new websocket client" Oct 23 17:37:52 volumio volumio[1063]: info: Connection to go-librespot Websocket established Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="authenticated as ravfed" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="dealer connection opened" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="initializing zeroconf session, username: ravfed" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="autoplay enabled: false" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="received connection id: MjQ2ZjllNmQtNGJkZC00Y2I5LTg3MTUtZjkxYmUzODQyYWY2K2RlYWxlcit0Y3A6Ly8wYWNhNTkxZi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQzcyNURDQ0U1RjkxQzkxN0JGRjMyQjY0Mjc3MDIyRDVEMDcwMjcwQTc0MzFGNURDNzNDOTJCQjcyQzU0NEI3MQ==" Oct 23 17:37:52 volumio go-librespot[3393]: time="2024-10-23T17:37:52+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 23 17:37:55 volumio volumio[1063]: info: Getting Spotify volume Oct 23 17:37:55 volumio volumio[1063]: info: Spotify volume: 100 Oct 23 17:37:55 volumio volumio[1063]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Oct 23 17:37:55 volumio volumio[1063]: info: CoreCommandRouter::volumioGetState Oct 23 17:37:55 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:37:55 volumio volumio[1063]: SPOTIFY: RECEIVED VOLUMIO VOLUME 61 Oct 23 17:37:55 volumio volumio[1063]: SPOTIFY: SPOTIFY VOLUME 100 Oct 23 17:37:55 volumio volumio[1063]: SPOTIFY: VOLUMIO VOLUME 61 Oct 23 17:37:55 volumio volumio[1063]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 23 17:37:55 volumio volumio[1063]: info: Setting Spotify Volume from Volumio: 61 Oct 23 17:37:57 volumio volumio[1063]: SPOTIFY: SETTING SPOTIFY VOLUME 61 Oct 23 17:37:57 volumio volumio[1063]: info: Sending Spotify command with payload to local API: /player/volume Oct 23 17:37:57 volumio go-librespot[3393]: time="2024-10-23T17:37:57+02:00" level=debug msg="update volume to 39976/65535" Oct 23 17:37:57 volumio go-librespot[3393]: time="2024-10-23T17:37:57+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 23 17:37:57 volumio go-librespot[3393]: time="2024-10-23T17:37:57+02:00" level=trace msg="emitting websocket event: volume" Oct 23 17:37:57 volumio volumio[1063]: SPOTIFY: received: {"type":"volume","data":{"value":61,"max":100}} Oct 23 17:37:57 volumio volumio[1063]: SPOTIFY: RECEIVED SPOTIFY VOLUME 61 Oct 23 17:38:03 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 17:38:03 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 17:38:03 volumio volumio[1063]: info: Discovery: Getting this device information Oct 23 17:38:03 volumio volumio[1063]: info: CoreCommandRouter::volumioGetState Oct 23 17:38:03 volumio volumio[1063]: info: CorePlayQueue::getTrack 0 Oct 23 17:38:03 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 17:38:04 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid Oct 23 17:38:04 volumio volumio[1063]: info: Pausing Remote Device: http://192.168.1.88 Oct 23 17:38:04 volumio volumio[1063]: info: Oct 23 17:38:04 volumio volumio[1063]: ---------------------------- Client requests Volumio pause Oct 23 17:38:04 volumio volumio[1063]: info: CoreCommandRouter::volumioPause Oct 23 17:38:04 volumio volumio[1063]: info: CoreStateMachine::pause Oct 23 17:38:04 volumio volumio[1063]: info: Done pausing: Oct 23 17:38:06 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid Oct 23 17:38:06 volumio volumio[1063]: info: Pausing Remote Device: http://192.168.1.88 Oct 23 17:38:06 volumio volumio[1063]: info: Oct 23 17:38:06 volumio volumio[1063]: ---------------------------- Client requests Volumio pause Oct 23 17:38:06 volumio volumio[1063]: info: CoreCommandRouter::volumioPause Oct 23 17:38:06 volumio volumio[1063]: info: CoreStateMachine::pause Oct 23 17:38:06 volumio volumio[1063]: info: Done pausing: Oct 23 17:38:07 volumio volumio[1063]: info: CoreCommandRouter::executeOnPlugin: multiroom , audioOutputPlay Oct 23 17:38:07 volumio volumio[1063]: info: Error : CoreCommandRouter::executeOnPlugin: No method [audioOutputPlay] in plugin multiroom Oct 23 17:38:07 volumio volumio[1063]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 17:38:07 volumio volumio[1063]: TypeError: Cannot read property 'then' of undefined Oct 23 17:38:07 volumio volumio[1063]: at outputs.audioOutputPlay (/volumio/app/plugins/audio_interface/outputs/index.js:367:9) Oct 23 17:38:07 volumio volumio[1063]: at CoreCommandRouter.audioOutputPlay (/volumio/app/index.js:2260:30) Oct 23 17:38:07 volumio volumio[1063]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1442:26) Oct 23 17:38:07 volumio volumio[1063]: at Socket.emit (events.js:400:28) Oct 23 17:38:07 volumio volumio[1063]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 23 17:38:07 volumio volumio[1063]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Oct 23 17:38:07 volumio volumio[1063]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 17:38:07 volumio sudo[3452]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-23 17:37 Oct 23 17:38:07 volumio sudo[3452]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:19:36 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="tinkerboard" VOLUMIO_DEVICENAME="Asus Tinkerboard" VOLUMIO_HASH="43b87fbef9c19ede18711bdf23c439c5"