-- Logs begin at Thu 2019-02-14 05:11:58 EST, end at Thu 2025-09-04 20:44:16 EDT. -- Sep 04 20:43:00 living-room-sr volumio[1088]: info: Sep 04 20:43:00 living-room-sr volumio[1088]: ---------------------------- Client requests Volumio play Sep 04 20:43:00 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioPlay Sep 04 20:43:00 living-room-sr volumio[1088]: info: CoreStateMachine::play index undefined Sep 04 20:43:00 living-room-sr volumio[1088]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 20:43:00 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:00 living-room-sr volumio[1088]: info: CoreStateMachine::startPlaybackTimer Sep 04 20:43:00 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:00 living-room-sr volumio[1088]: info: [1757032980973] ControllerSpotify::clearAddPlayTrack Sep 04 20:43:00 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/play Sep 04 20:43:00 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:00 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:00 living-room-sr volumio[1088]: info: Listing playlists Sep 04 20:43:00 living-room-sr volumio[1088]: info: Listing playlists Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="resolved context of track" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=trace msg="emitting websocket event: will_play" Sep 04 20:43:01 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","play_origin":"go-librespot"}} Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="selected format OGG_VORBIS_320 (af0568de7e256c18767bfeeff7895473da6bab0e)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="requested aes key for file af0568de7e256c18767bfeeff7895473da6bab0e, gid: 7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="fetched first chunk of 12, total size is 5995396 bytes" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="created new output device" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=info msg="loaded track \"oops!\" (paused: false, position: 1ms, duration: 139759ms, prefetched: false)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=trace msg="scheduling prefetch in 110s" Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=trace msg="emitting websocket event: metadata" Sep 04 20:43:01 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","name":"oops!","artist_names":["Yung Gravy"],"album_name":"Gasanova","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c5e844c860c9717785b7aaa2","position":1,"duration":139759,"release_date":"year:2020 month:10 day:2","track_number":5,"disc_number":1}} Sep 04 20:43:01 living-room-sr go-librespot[2073]: time="2025-09-04T20:43:01-04:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:01 living-room-sr go-librespot[2073]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Sep 04 20:43:01 living-room-sr go-librespot[2073]: Aborted Sep 04 20:43:01 living-room-sr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Sep 04 20:43:01 living-room-sr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:43:01 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket closed Sep 04 20:43:04 living-room-sr volumio[1088]: info: Sep 04 20:43:04 living-room-sr volumio[1088]: ---------------------------- Client requests Volumio play Sep 04 20:43:04 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioPlay Sep 04 20:43:04 living-room-sr volumio[1088]: info: CoreStateMachine::play index undefined Sep 04 20:43:04 living-room-sr volumio[1088]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 20:43:04 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:04 living-room-sr volumio[1088]: info: CoreStateMachine::startPlaybackTimer Sep 04 20:43:04 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:04 living-room-sr volumio[1088]: info: [1757032984295] ControllerSpotify::clearAddPlayTrack Sep 04 20:43:04 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/play Sep 04 20:43:04 living-room-sr volumio[1088]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:43:04 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:04 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:04 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:04 living-room-sr volumio[1088]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:43:04 living-room-sr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:43:04 living-room-sr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Sep 04 20:43:04 living-room-sr systemd[1]: Stopped go-librespot Daemon. Sep 04 20:43:04 living-room-sr systemd[1]: Started go-librespot Daemon. Sep 04 20:43:04 living-room-sr go-librespot[2176]: go-librespot daemon starting... Sep 04 20:43:04 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:04-04:00" level=info msg="running go-librespot 0.3.2" Sep 04 20:43:04 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:04-04:00" level=debug msg="app state loaded" Sep 04 20:43:04 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:04-04:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=info msg="zeroconf server listening on port 43653" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="obtained new client token: AAAdfM37Y7lHbRtuPdsP6aYpijx8a/4qBh70X1VZ8AMUqitmMiCj+kz+iJEHnA/XdtKw/xcBc+TRa+PzfgfG4eTa/Oxn3BGMcRisdE7/kaHU7oSjv8u+ZHGl1GJ0c70dV0FKaE8eR18WQh7ZhBJ5Czq9ZlG9J+ICDre3f30RadgL61O1EvcvzL/3THBaF2RcNf3MAiWBd5H+Zt32axTNZB3Y8gmiONTcS8+DDMIFmYb1SnSwxB9gTpkbdw==" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="completed keyexchange" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="completed challenge" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=info msg="authenticated AP" username="12*****33" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=info msg="authenticated Login5" username="12*****33" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="initializing zeroconf session" username="12*****33" Sep 04 20:43:05 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:05 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="dealer connection opened" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=trace msg="starting accesspoint recv loop" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=trace msg="starting dealer recv loop" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=trace msg="received accesspoint ping" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=debug msg="received connection id: MTMyMjIxYzEtZWM1...NkY5MTNENkNGQg==" Sep 04 20:43:05 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:05-04:00" level=trace msg="received accesspoint pong ack" Sep 04 20:43:06 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:06-04:00" level=debug msg="put connect state because NEW_DEVICE" Sep 04 20:43:07 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:07 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:07-04:00" level=debug msg="new websocket client" Sep 04 20:43:07 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket established Sep 04 20:43:10 living-room-sr volumio[1088]: info: Getting Spotify volume Sep 04 20:43:10 living-room-sr volumio[1088]: info: Spotify volume: 100 Sep 04 20:43:10 living-room-sr volumio[1088]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Sep 04 20:43:10 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:10 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:10 living-room-sr volumio[1088]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 Sep 04 20:43:10 living-room-sr volumio[1088]: SPOTIFY: SPOTIFY VOLUME 100 Sep 04 20:43:10 living-room-sr volumio[1088]: SPOTIFY: VOLUMIO VOLUME 84 Sep 04 20:43:10 living-room-sr volumio[1088]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 04 20:43:10 living-room-sr volumio[1088]: info: Setting Spotify Volume from Volumio: 84 Sep 04 20:43:10 living-room-sr volumio[1088]: info: Sep 04 20:43:10 living-room-sr volumio[1088]: ---------------------------- Client requests Volumio play Sep 04 20:43:10 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioPlay Sep 04 20:43:10 living-room-sr volumio[1088]: info: CoreStateMachine::play index undefined Sep 04 20:43:10 living-room-sr volumio[1088]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 20:43:10 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:10 living-room-sr volumio[1088]: info: CoreStateMachine::startPlaybackTimer Sep 04 20:43:10 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:10 living-room-sr volumio[1088]: info: [1757032990934] ControllerSpotify::clearAddPlayTrack Sep 04 20:43:10 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/play Sep 04 20:43:10 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:10 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="resolved context of track" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=trace msg="emitting websocket event: will_play" Sep 04 20:43:11 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","play_origin":"go-librespot"}} Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="selected format OGG_VORBIS_320 (af0568de7e256c18767bfeeff7895473da6bab0e)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="requested aes key for file af0568de7e256c18767bfeeff7895473da6bab0e, gid: 7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="fetched first chunk of 12, total size is 5995396 bytes" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="created new output device" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=info msg="loaded track \"oops!\" (paused: false, position: 0ms, duration: 139759ms, prefetched: false)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=trace msg="scheduling prefetch in 110s" Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=trace msg="emitting websocket event: metadata" Sep 04 20:43:11 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","name":"oops!","artist_names":["Yung Gravy"],"album_name":"Gasanova","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c5e844c860c9717785b7aaa2","position":0,"duration":139759,"release_date":"year:2020 month:10 day:2","track_number":5,"disc_number":1}} Sep 04 20:43:11 living-room-sr go-librespot[2176]: time="2025-09-04T20:43:11-04:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:11 living-room-sr go-librespot[2176]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Sep 04 20:43:11 living-room-sr go-librespot[2176]: Aborted Sep 04 20:43:11 living-room-sr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Sep 04 20:43:11 living-room-sr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:43:11 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket closed Sep 04 20:43:12 living-room-sr volumio[1088]: SPOTIFY: SETTING SPOTIFY VOLUME 84 Sep 04 20:43:12 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/volume Sep 04 20:43:12 living-room-sr volumio[1088]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:43:14 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:14 living-room-sr volumio[1088]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:43:14 living-room-sr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:43:14 living-room-sr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Sep 04 20:43:14 living-room-sr systemd[1]: Stopped go-librespot Daemon. Sep 04 20:43:14 living-room-sr systemd[1]: Started go-librespot Daemon. Sep 04 20:43:14 living-room-sr go-librespot[2204]: go-librespot daemon starting... Sep 04 20:43:14 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:14-04:00" level=info msg="running go-librespot 0.3.2" Sep 04 20:43:14 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:14-04:00" level=debug msg="app state loaded" Sep 04 20:43:14 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:14-04:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=info msg="zeroconf server listening on port 46069" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="obtained new client token: AACOVgbAQ3H6ufHzdOkRV7mAI7dpNusH/UsHnOu7iFPTzU4IyVbfIfKD8dYLSAjf/VWCv81uCfqMDpsfOaJf/f2HRGeULn72+oy8M5grTxz0cPicjjS6EVZCv4IONyn9QUvBTUcWhcMEioBJgs4EpQgahiAn4HA99nrEZFUp0DQvrHsqyteWNiNelFxOrDro4clAO+9sOyeY/ykSR35uC+X5XQAYHl/somWAlHPKtJWUoR1urkCXtYkaQA==" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="completed keyexchange" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="completed challenge" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=info msg="authenticated AP" username="12*****33" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=info msg="authenticated Login5" username="12*****33" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="initializing zeroconf session" username="12*****33" Sep 04 20:43:15 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:15 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="dealer connection opened" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=trace msg="starting accesspoint recv loop" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=trace msg="starting dealer recv loop" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=trace msg="received accesspoint ping" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=debug msg="received connection id: ZTljZjhhNzYtYWNl...RTcyMjc0M0E1MQ==" Sep 04 20:43:15 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:15-04:00" level=trace msg="received accesspoint pong ack" Sep 04 20:43:17 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:17 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:17-04:00" level=debug msg="new websocket client" Sep 04 20:43:17 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket established Sep 04 20:43:19 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetVisibleSources Sep 04 20:43:19 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 04 20:43:20 living-room-sr volumio[1088]: info: Getting Spotify volume Sep 04 20:43:20 living-room-sr volumio[1088]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Sep 04 20:43:20 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:20 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:20 living-room-sr volumio[1088]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 Sep 04 20:43:21 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:21-04:00" level=debug msg="put connect state because NEW_DEVICE" Sep 04 20:43:21 living-room-sr volumio[1088]: info: Spotify volume: 100 Sep 04 20:43:22 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Sep 04 20:43:22 living-room-sr volumio[1088]: info: In handleBrowseUri, curUri=spotify Sep 04 20:43:22 living-room-sr volumio[1088]: info: New access token = BQDh3Hp4Bx301tKF2TyzjAh2mhcr9u6-XsGbUOUxTi6MALr3DlTzbpoXSIT-w-ZnnbCMxhxNvJ0rMh3RsBeoh6FgAR2PwvBi4W54tK3IZ7zgEnZFT_r6SjscNzPoVxB7W_vy2fwre0fck7-8gHSOmuY0QZRm-6Gz11DeSx3qdU3op1DYs3AQQplPmNkSTF6l_PhC8MJDlWNg7fgiZu6McX5pey3WrP0_GKcmooWHLls0kuCiTSvRGwH1b080W95qswG6Qx9ccLvE5CbrynHzY0Lshg Sep 04 20:43:22 living-room-sr volumio[1088]: info: New access token = BQCyeA97n6KvSfMCLgxf5Ud3tv_7fJLLw3MmDan8E3tFqZBxg8PqyURluTwoZQpvWfupSaGWUJYfPd6jNphHvz0KSK698eM6OsApyDtBry-6fFNTLG-UG26zyihASnyJeycoENF3a03L1TP_e6eD0qdV-LLiyGjxYTkXerbpUCo-NBMKU5CQUsaBk--U36YImoUHcXOeRGGfoEhSjnsTPrYMsnhFn8l40bPWYwANF7T0rW16BsJjJdiepl3hqUQprhcAutl755Ozf6J2L4Ftge5yXA Sep 04 20:43:22 living-room-sr volumio[1088]: info: New access token = BQD0JKjHx_AhjDyavCSoNpfpJgwK9QPqdkY-wbn418kOcW6DXu1P6TwAWpyttLqzKOkiYWB7WprXIErBfzUE39pF3YspALA81BqJDbFhOtdwdfLS1x0xHABA_B1hZRz8ZbkvKXpsNDjhMJIhGlnGaFu-ny-5tiEBWHLIh9Tys0fJySP44AVF_YzarMFkESuB4lcCv3GQAPfCEmVV9JP6tP4XXuVlgFxAM99pR1H_-bgEIrvd6NaZR1cc2_MpF_X-awH4QQuSg1Z743-39ztThu7pRA Sep 04 20:43:25 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Sep 04 20:43:25 living-room-sr volumio[1088]: info: In handleBrowseUri, curUri=spotify/playlists Sep 04 20:43:25 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:25 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:25 living-room-sr volumio[1088]: info: Listing playlists Sep 04 20:43:25 living-room-sr volumio[1088]: info: Listing playlists Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::ClearQueue Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::stop Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 20:43:27 living-room-sr volumio[1088]: info: CorePlayQueue::clearPlayQueue Sep 04 20:43:27 living-room-sr volumio[1088]: info: CorePlayQueue::saveQueue Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioPushQueue Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::addQueueItems Sep 04 20:43:27 living-room-sr volumio[1088]: info: CorePlayQueue::addQueueItems Sep 04 20:43:27 living-room-sr volumio[1088]: info: Preload queue cleared Sep 04 20:43:27 living-room-sr volumio[1088]: info: Adding Item to queue: spotify:user:spotify:playlist:37i9dQZF1E4BKkta8gHekM Sep 04 20:43:27 living-room-sr volumio[1088]: info: Exploding uri spotify:user:spotify:playlist:37i9dQZF1E4BKkta8gHekM in service spop Sep 04 20:43:27 living-room-sr volumio[1088]: SPOTIFY: EXPLODING URI:spotify:user:spotify:playlist:37i9dQZF1E4BKkta8gHekM Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioPushQueue Sep 04 20:43:27 living-room-sr volumio[1088]: info: CorePlayQueue::saveQueue Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::updateTrackBlock Sep 04 20:43:27 living-room-sr volumio[1088]: info: CorePlayQueue::getTrackBlock Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioPlay Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::play index 0 Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::stop Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::play index undefined Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 20:43:27 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreStateMachine::startPlaybackTimer Sep 04 20:43:27 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:27 living-room-sr volumio[1088]: info: [1757033007793] ControllerSpotify::clearAddPlayTrack Sep 04 20:43:27 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/play Sep 04 20:43:27 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:27 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:27 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:27-04:00" level=debug msg="resolved context of track" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:27 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:27-04:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:27 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:27-04:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:27 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:27-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:27 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:27-04:00" level=trace msg="emitting websocket event: will_play" Sep 04 20:43:27 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","play_origin":"go-librespot"}} Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=debug msg="selected format OGG_VORBIS_320 (af0568de7e256c18767bfeeff7895473da6bab0e)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=debug msg="requested aes key for file af0568de7e256c18767bfeeff7895473da6bab0e, gid: 7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=debug msg="fetched first chunk of 12, total size is 5995396 bytes" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=debug msg="created new output device" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=info msg="loaded track \"oops!\" (paused: false, position: 0ms, duration: 139759ms, prefetched: false)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=trace msg="scheduling prefetch in 110s" Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=trace msg="emitting websocket event: metadata" Sep 04 20:43:28 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","name":"oops!","artist_names":["Yung Gravy"],"album_name":"Gasanova","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c5e844c860c9717785b7aaa2","position":0,"duration":139759,"release_date":"year:2020 month:10 day:2","track_number":5,"disc_number":1}} Sep 04 20:43:28 living-room-sr go-librespot[2204]: time="2025-09-04T20:43:28-04:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:28 living-room-sr go-librespot[2204]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Sep 04 20:43:28 living-room-sr go-librespot[2204]: Aborted Sep 04 20:43:28 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket closed Sep 04 20:43:28 living-room-sr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Sep 04 20:43:28 living-room-sr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:43:31 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:31 living-room-sr volumio[1088]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:43:31 living-room-sr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:43:31 living-room-sr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Sep 04 20:43:31 living-room-sr systemd[1]: Stopped go-librespot Daemon. Sep 04 20:43:31 living-room-sr systemd[1]: Started go-librespot Daemon. Sep 04 20:43:31 living-room-sr go-librespot[2243]: go-librespot daemon starting... Sep 04 20:43:31 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:31-04:00" level=info msg="running go-librespot 0.3.2" Sep 04 20:43:31 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:31-04:00" level=debug msg="app state loaded" Sep 04 20:43:31 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:31-04:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=info msg="zeroconf server listening on port 37481" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="obtained new client token: AADmv7MfBIU5KW5J/aNfonobH2m59LbS4fhHfqc/GLrxRHRec7bE13JdlciyJAb/2EQpsab6gSEsrVAzxdhWAIJyRKlw+8X72duxvADUKl89NCj2mCTNHn1J9FRmOepU1Zt03C5fI78JrP9n8m6ncQeAOTzvV7YzfjZzqYvGkqg/Puoho8GLBHp3j4+GwLkdN5QTuldarTJzq6Kwl+tmGJfaVomNLmZEMBBmcO/tgHIZm5Arv7mFbmogXw==" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="completed keyexchange" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="completed challenge" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=info msg="authenticated AP" username="12*****33" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=info msg="authenticated Login5" username="12*****33" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="initializing zeroconf session" username="12*****33" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="dealer connection opened" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=trace msg="starting accesspoint recv loop" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=trace msg="starting dealer recv loop" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=trace msg="received accesspoint ping" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=debug msg="received connection id: NjY0MmU4NDMtOTdk...NUQ3QjJGRkVCRQ==" Sep 04 20:43:32 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:32-04:00" level=trace msg="received accesspoint pong ack" Sep 04 20:43:33 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:33-04:00" level=debug msg="put connect state because NEW_DEVICE" Sep 04 20:43:34 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:34 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:34-04:00" level=debug msg="new websocket client" Sep 04 20:43:34 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket established Sep 04 20:43:35 living-room-sr volumio[1088]: info: Sep 04 20:43:35 living-room-sr volumio[1088]: ---------------------------- Client requests Volumio play Sep 04 20:43:35 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioPlay Sep 04 20:43:35 living-room-sr volumio[1088]: info: CoreStateMachine::play index undefined Sep 04 20:43:35 living-room-sr volumio[1088]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 20:43:35 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:35 living-room-sr volumio[1088]: info: CoreStateMachine::startPlaybackTimer Sep 04 20:43:35 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:35 living-room-sr volumio[1088]: info: [1757033015584] ControllerSpotify::clearAddPlayTrack Sep 04 20:43:35 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/play Sep 04 20:43:35 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:35 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:35 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:35-04:00" level=debug msg="resolved context of track" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:35 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:35-04:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:35 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:35-04:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:35 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:35-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:35 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:35-04:00" level=trace msg="emitting websocket event: will_play" Sep 04 20:43:35 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","play_origin":"go-librespot"}} Sep 04 20:43:35 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:35 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:35 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:35-04:00" level=debug msg="selected format OGG_VORBIS_320 (af0568de7e256c18767bfeeff7895473da6bab0e)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:35 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:35-04:00" level=debug msg="requested aes key for file af0568de7e256c18767bfeeff7895473da6bab0e, gid: 7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=debug msg="fetched first chunk of 12, total size is 5995396 bytes" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=debug msg="created new output device" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=info msg="loaded track \"oops!\" (paused: false, position: 0ms, duration: 139759ms, prefetched: false)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=trace msg="scheduling prefetch in 110s" Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=trace msg="emitting websocket event: metadata" Sep 04 20:43:36 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","name":"oops!","artist_names":["Yung Gravy"],"album_name":"Gasanova","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c5e844c860c9717785b7aaa2","position":0,"duration":139759,"release_date":"year:2020 month:10 day:2","track_number":5,"disc_number":1}} Sep 04 20:43:36 living-room-sr go-librespot[2243]: time="2025-09-04T20:43:36-04:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:36 living-room-sr go-librespot[2243]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Sep 04 20:43:36 living-room-sr go-librespot[2243]: Aborted Sep 04 20:43:36 living-room-sr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Sep 04 20:43:36 living-room-sr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:43:36 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket closed Sep 04 20:43:37 living-room-sr volumio[1088]: info: Getting Spotify volume Sep 04 20:43:37 living-room-sr volumio[1088]: (node:1088) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:43:37 living-room-sr volumio[1088]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 04 20:43:37 living-room-sr volumio[1088]: (Use `node --trace-warnings ...` to show where the warning was created) Sep 04 20:43:37 living-room-sr volumio[1088]: (node:1088) 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: 1) Sep 04 20:43:37 living-room-sr volumio[1088]: (node:1088) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. Sep 04 20:43:37 living-room-sr volumio[1088]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Sep 04 20:43:37 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:37 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:37 living-room-sr volumio[1088]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 Sep 04 20:43:37 living-room-sr volumio[1088]: SPOTIFY: SPOTIFY VOLUME 100 Sep 04 20:43:37 living-room-sr volumio[1088]: SPOTIFY: VOLUMIO VOLUME 84 Sep 04 20:43:37 living-room-sr volumio[1088]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 04 20:43:37 living-room-sr volumio[1088]: info: Setting Spotify Volume from Volumio: 84 Sep 04 20:43:39 living-room-sr volumio[1088]: SPOTIFY: SETTING SPOTIFY VOLUME 84 Sep 04 20:43:39 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/volume Sep 04 20:43:39 living-room-sr volumio[1088]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:43:39 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:39 living-room-sr volumio[1088]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:43:39 living-room-sr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:43:39 living-room-sr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Sep 04 20:43:39 living-room-sr systemd[1]: Stopped go-librespot Daemon. Sep 04 20:43:39 living-room-sr systemd[1]: Started go-librespot Daemon. Sep 04 20:43:39 living-room-sr go-librespot[2271]: go-librespot daemon starting... Sep 04 20:43:39 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:39-04:00" level=info msg="running go-librespot 0.3.2" Sep 04 20:43:39 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:39-04:00" level=debug msg="app state loaded" Sep 04 20:43:39 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:39-04:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 04 20:43:39 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:39-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 04 20:43:39 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:39-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 04 20:43:39 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:39-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 04 20:43:39 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:39-04:00" level=info msg="zeroconf server listening on port 45983" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="obtained new client token: AAAciU960VRxBKdVyrtPWKu9PDzhtqoYWPwb1U5pZkPZQzMiITCSBBAyawHGsfirTaKEH/e7Bzlu1q7NPQjvZZNb/SfMWcc8YKmfOf7sGOh/3jbnCsXbh0ZEUbhOv6zDUeHamCUaZbvm3w2CCZyfBfLbZyHhYePWRMn16UxXu9b9HxJsYQsH0GqAPnHulWos4DsvwrfdHfnh1YGQU1vSybYQkf1xRsh7ATEoweRLIK3C8+WwJhppHfc=" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="completed keyexchange" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="completed challenge" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=info msg="authenticated AP" username="12*****33" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=info msg="authenticated Login5" username="12*****33" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="initializing zeroconf session" username="12*****33" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="dealer connection opened" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=trace msg="starting accesspoint recv loop" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=trace msg="starting dealer recv loop" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=trace msg="received accesspoint ping" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="received connection id: MTBkOTE2NWYtYmVj...OEZDMENGMjM1Mw==" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=trace msg="received accesspoint pong ack" Sep 04 20:43:40 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:40-04:00" level=debug msg="put connect state because NEW_DEVICE" Sep 04 20:43:42 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:42 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:42-04:00" level=debug msg="new websocket client" Sep 04 20:43:42 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket established Sep 04 20:43:45 living-room-sr volumio[1088]: info: Getting Spotify volume Sep 04 20:43:45 living-room-sr volumio[1088]: info: Spotify volume: 100 Sep 04 20:43:45 living-room-sr volumio[1088]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Sep 04 20:43:45 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:45 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:45 living-room-sr volumio[1088]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 Sep 04 20:43:45 living-room-sr volumio[1088]: SPOTIFY: SPOTIFY VOLUME 100 Sep 04 20:43:45 living-room-sr volumio[1088]: SPOTIFY: VOLUMIO VOLUME 84 Sep 04 20:43:45 living-room-sr volumio[1088]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 04 20:43:45 living-room-sr volumio[1088]: info: Setting Spotify Volume from Volumio: 84 Sep 04 20:43:45 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:45 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:45 living-room-sr volumio[1088]: info: Listing playlists Sep 04 20:43:45 living-room-sr volumio[1088]: info: Listing playlists Sep 04 20:43:46 living-room-sr volumio[1088]: SPOTIFY: SETTING SPOTIFY VOLUME 84 Sep 04 20:43:46 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/volume Sep 04 20:43:46 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:46-04:00" level=debug msg="update volume requested to 55049/65535" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=trace msg="emitting websocket event: volume" Sep 04 20:43:47 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"volume","data":{"value":84,"max":100}} Sep 04 20:43:47 living-room-sr volumio[1088]: SPOTIFY: RECEIVED SPOTIFY VOLUME 84 Sep 04 20:43:47 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioPlay Sep 04 20:43:47 living-room-sr volumio[1088]: info: CoreStateMachine::play index undefined Sep 04 20:43:47 living-room-sr volumio[1088]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 20:43:47 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:47 living-room-sr volumio[1088]: info: CoreStateMachine::startPlaybackTimer Sep 04 20:43:47 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:47 living-room-sr volumio[1088]: info: [1757033027323] ControllerSpotify::clearAddPlayTrack Sep 04 20:43:47 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/play Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=debug msg="resolved context of track" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=trace msg="emitting websocket event: will_play" Sep 04 20:43:47 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","play_origin":"go-librespot"}} Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=debug msg="selected format OGG_VORBIS_320 (af0568de7e256c18767bfeeff7895473da6bab0e)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=debug msg="requested aes key for file af0568de7e256c18767bfeeff7895473da6bab0e, gid: 7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=debug msg="fetched first chunk of 12, total size is 5995396 bytes" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=debug msg="created new output device" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 04 20:43:47 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:47-04:00" level=info msg="loaded track \"oops!\" (paused: false, position: 1ms, duration: 139759ms, prefetched: false)" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:48 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:48-04:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:48 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:48-04:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:48 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:48-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 04 20:43:48 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:48-04:00" level=trace msg="scheduling prefetch in 110s" Sep 04 20:43:48 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:48-04:00" level=trace msg="emitting websocket event: metadata" Sep 04 20:43:48 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7L6G0wpIUiPXuvoo7qhb06","name":"oops!","artist_names":["Yung Gravy"],"album_name":"Gasanova","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c5e844c860c9717785b7aaa2","position":1,"duration":139759,"release_date":"year:2020 month:10 day:2","track_number":5,"disc_number":1}} Sep 04 20:43:48 living-room-sr go-librespot[2271]: time="2025-09-04T20:43:48-04:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:7L6G0wpIUiPXuvoo7qhb06" Sep 04 20:43:48 living-room-sr go-librespot[2271]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Sep 04 20:43:48 living-room-sr go-librespot[2271]: Aborted Sep 04 20:43:48 living-room-sr systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Sep 04 20:43:48 living-room-sr systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:43:48 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket closed Sep 04 20:43:51 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:51 living-room-sr volumio[1088]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:43:51 living-room-sr systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:43:51 living-room-sr systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Sep 04 20:43:51 living-room-sr systemd[1]: Stopped go-librespot Daemon. Sep 04 20:43:51 living-room-sr volumiologrotate[624]: ls: cannot access '/var/log/samba/log.wb-LIVING': No such file or directory Sep 04 20:43:51 living-room-sr systemd[1]: Started go-librespot Daemon. Sep 04 20:43:51 living-room-sr volumiologrotate[624]: ls: cannot access 'ROOM': No such file or directory Sep 04 20:43:51 living-room-sr volumiologrotate[624]: ls: cannot access 'SR': No such file or directory Sep 04 20:43:51 living-room-sr go-librespot[2305]: go-librespot daemon starting... Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=info msg="running go-librespot 0.3.2" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=debug msg="app state loaded" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=info msg="zeroconf server listening on port 34837" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=debug msg="obtained new client token: AAAh3C6ovJ49ttdBKazB/1ao4UKxQPgpBCsaDqZRppuYcwEXu0qGEZU6BYDdeNwPyTRRNLy7EMfCBUyICLWFooDvFGBQPObrEMdGraf0GNfvfW5ZFEnoVh+EVx3VaNB96sOqCZegAe5pgHLJNHZIwf4//dBU7pckB8k8gKi3aE5zmQfuUf3voY05lu1mnfT3z8AiF+S7O4gjk+O6VAeeab1HGhZeIVGpHhoENH6POwQXXAYvkn+I3mmRyA==" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=debug msg="completed keyexchange" Sep 04 20:43:51 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:51-04:00" level=debug msg="completed challenge" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=info msg="authenticated AP" username="12*****33" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=info msg="authenticated Login5" username="12*****33" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=debug msg="initializing zeroconf session" username="12*****33" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=debug msg="dealer connection opened" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=trace msg="starting accesspoint recv loop" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=trace msg="starting dealer recv loop" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=trace msg="received accesspoint ping" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=debug msg="received connection id: Mzc1YjcxNGYtZjcz...ODA5M0ZCNzBEOA==" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=trace msg="received accesspoint pong ack" Sep 04 20:43:52 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:52-04:00" level=debug msg="put connect state because NEW_DEVICE" Sep 04 20:43:54 living-room-sr volumio[1088]: info: Initializing connection to go-librespot Websocket Sep 04 20:43:54 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:54-04:00" level=debug msg="new websocket client" Sep 04 20:43:54 living-room-sr volumio[1088]: info: Connection to go-librespot Websocket established Sep 04 20:43:55 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:55 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:57 living-room-sr volumio[1088]: info: Getting Spotify volume Sep 04 20:43:57 living-room-sr volumio[1088]: info: Spotify volume: 100 Sep 04 20:43:57 living-room-sr volumio[1088]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Sep 04 20:43:57 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:43:57 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:43:57 living-room-sr volumio[1088]: SPOTIFY: RECEIVED VOLUMIO VOLUME 84 Sep 04 20:43:57 living-room-sr volumio[1088]: SPOTIFY: SPOTIFY VOLUME 100 Sep 04 20:43:57 living-room-sr volumio[1088]: SPOTIFY: VOLUMIO VOLUME 84 Sep 04 20:43:57 living-room-sr volumio[1088]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 04 20:43:57 living-room-sr volumio[1088]: info: Setting Spotify Volume from Volumio: 84 Sep 04 20:43:58 living-room-sr volumio[1088]: SPOTIFY: SETTING SPOTIFY VOLUME 84 Sep 04 20:43:58 living-room-sr volumio[1088]: info: Sending Spotify command with payload to local API: /player/volume Sep 04 20:43:58 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:58-04:00" level=debug msg="update volume requested to 55049/65535" Sep 04 20:43:58 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:58-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 04 20:43:58 living-room-sr go-librespot[2305]: time="2025-09-04T20:43:58-04:00" level=trace msg="emitting websocket event: volume" Sep 04 20:43:58 living-room-sr volumio[1088]: SPOTIFY: received: {"type":"volume","data":{"value":84,"max":100}} Sep 04 20:43:58 living-room-sr volumio[1088]: SPOTIFY: RECEIVED SPOTIFY VOLUME 84 Sep 04 20:43:59 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetQueue Sep 04 20:43:59 living-room-sr volumio[1088]: info: CoreStateMachine::getQueue Sep 04 20:43:59 living-room-sr volumio[1088]: info: CorePlayQueue::getQueue Sep 04 20:44:05 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 04 20:44:05 living-room-sr volumio[1088]: info: Preload queue cleared Sep 04 20:44:05 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:44:05 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:44:05 living-room-sr volumio[1088]: info: Listing playlists Sep 04 20:44:05 living-room-sr volumio[1088]: info: Listing playlists Sep 04 20:44:06 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 04 20:44:06 living-room-sr volumio[1088]: info: Preload queue cleared Sep 04 20:44:07 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 04 20:44:07 living-room-sr volumio[1088]: info: Preload queue cleared Sep 04 20:44:08 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 04 20:44:09 living-room-sr volumio[1088]: info: Preload queue cleared Sep 04 20:44:11 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 04 20:44:14 living-room-sr volumio[1088]: info: Preload queue cleared Sep 04 20:44:15 living-room-sr volumio[1088]: info: CoreCommandRouter::volumioGetState Sep 04 20:44:15 living-room-sr volumio[1088]: info: CorePlayQueue::getTrack 0 Sep 04 20:44:16 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 04 20:44:16 living-room-sr volumio[1088]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 04 20:44:16 living-room-sr volumio[1088]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 04 20:44:16 living-room-sr volumio[1088]: TypeError: Cannot read property 'length' of undefined Sep 04 20:44:16 living-room-sr volumio[1088]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Sep 04 20:44:16 living-room-sr volumio[1088]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Sep 04 20:44:16 living-room-sr volumio[1088]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Sep 04 20:44:16 living-room-sr volumio[1088]: at Parser.emit (events.js:315:20) Sep 04 20:44:16 living-room-sr volumio[1088]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Sep 04 20:44:16 living-room-sr volumio[1088]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Sep 04 20:44:16 living-room-sr volumio[1088]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Sep 04 20:44:16 living-room-sr volumio[1088]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Sep 04 20:44:16 living-room-sr volumio[1088]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Sep 04 20:44:16 living-room-sr volumio[1088]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Sep 04 20:44:16 living-room-sr volumio[1088]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Sep 04 20:44:16 living-room-sr volumio[1088]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Sep 04 20:44:16 living-room-sr volumio[1088]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Sep 04 20:44:16 living-room-sr volumio[1088]: at IncomingMessage.emit (events.js:327:22) Sep 04 20:44:16 living-room-sr volumio[1088]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 04 20:44:16 living-room-sr volumio[1088]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 04 20:44:16 living-room-sr volumio[1088]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 04 20:44:16 living-room-sr sudo[2391]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-04 20:43 Sep 04 20:44:16 living-room-sr sudo[2391]: 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"