-- Logs begin at Thu 2019-02-14 17:11:58 +07, end at Mon 2025-06-02 01:39:10 +07. -- Jun 02 01:38:01 volumio volumio[976]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 02 01:38:08 volumio volumio[976]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jun 02 01:38:08 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jun 02 01:38:08 volumio volumio[976]: info: Creating Spotify config file Jun 02 01:38:08 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 02 01:38:08 volumio volumio[976]: info: Spotify config file written Jun 02 01:38:08 volumio sudo[2256]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 02 01:38:08 volumio sudo[2256]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 02 01:38:08 volumio ntpd[764]: Soliciting pool server 115.165.161.155 Jun 02 01:38:08 volumio systemd[1]: Stopping go-librespot Daemon... Jun 02 01:38:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jun 02 01:38:08 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jun 02 01:38:08 volumio systemd[1]: Stopped go-librespot Daemon. Jun 02 01:38:08 volumio volumio[976]: info: Connection to go-librespot Websocket closed Jun 02 01:38:08 volumio systemd[1]: Started go-librespot Daemon. Jun 02 01:38:08 volumio go-librespot[2258]: go-librespot daemon starting... Jun 02 01:38:08 volumio sudo[2256]: pam_unix(sudo:session): session closed for user root Jun 02 01:38:08 volumio go-librespot[2258]: time="2025-06-02T01:38:08+07:00" level=info msg="running go-librespot 0.2.0" Jun 02 01:38:08 volumio go-librespot[2258]: time="2025-06-02T01:38:08+07:00" level=debug msg="app state loaded" Jun 02 01:38:08 volumio go-librespot[2258]: time="2025-06-02T01:38:08+07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 02 01:38:08 volumio go-librespot[2258]: time="2025-06-02T01:38:08+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 02 01:38:08 volumio go-librespot[2258]: time="2025-06-02T01:38:08+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 02 01:38:08 volumio go-librespot[2258]: time="2025-06-02T01:38:08+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 02 01:38:08 volumio go-librespot[2258]: time="2025-06-02T01:38:08+07:00" level=info msg="zeroconf server listening on port 34243" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="obtained new client token: AADwUx0ICg8wN5svz+veKVTKg9veukUWNWHMoqYq1CsYLomyXpVuChSgDsCd8bcQMfvGWZ9Az1olOzg7MXAnaxtsCvZUgvi0Zd/P8YlxP6ilwmhiAl/sVlNyU+iXNCPApPXo2DbTEiqXZF615elenc8MfvnDAbug08nIb0pVH8Tm8JSgj8oqBo20rKAjP3WyWHEXtRi0FY7D5Ccsu1UdivVSlAko+ajtt00dR9QHokBqRcnmpUd3ZcG6" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="completed keyexchange" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="completed challenge" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=info msg="authenticated AP as qcwen1m8f5rq7627leoulbath" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=info msg="authenticated Login5 as qcwen1m8f5rq7627leoulbath" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="initializing zeroconf session, username: qcwen1m8f5rq7627leoulbath" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="dealer connection opened" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=trace msg="starting accesspoint recv loop" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=trace msg="starting dealer recv loop" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=trace msg="received accesspoint ping" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="received connection id: ZWJjOWY5ZGQtMWIwMS00Y2EzLWIwOTAtYmIwOTZmZmNmZjg2K2RlYWxlcit0Y3A6Ly8wYWM5NDgwNi5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArRTZCMzE4NERGNUI3NTM0MURCQzY2RDIyQTFGNjFBOTYwQzE2MjZBRjU3NTMxRkFEMkIzMUIyMDc5MDhCM0IyOQ==" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=trace msg="received accesspoint pong ack" Jun 02 01:38:09 volumio go-librespot[2258]: time="2025-06-02T01:38:09+07:00" level=debug msg="put connect state because NEW_DEVICE" Jun 02 01:38:11 volumio ntpd[764]: Soliciting pool server 103.184.124.254 Jun 02 01:38:11 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Jun 02 01:38:11 volumio ntpd[764]: Soliciting pool server 103.184.124.254 Jun 02 01:38:11 volumio go-librespot[2258]: time="2025-06-02T01:38:11+07:00" level=debug msg="new websocket client" Jun 02 01:38:11 volumio volumio[976]: info: Connection to go-librespot Websocket established Jun 02 01:38:11 volumio volumio[976]: info: go-librespot daemon successfully initialized Jun 02 01:38:14 volumio ntpd[764]: Soliciting pool server 103.184.124.254 Jun 02 01:38:14 volumio volumio[976]: info: Getting Spotify volume Jun 02 01:38:14 volumio volumio[976]: info: Spotify volume: 100 Jun 02 01:38:14 volumio volumio[976]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 02 01:38:14 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 02 01:38:14 volumio volumio[976]: info: CorePlayQueue::getTrack 6 Jun 02 01:38:14 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jun 02 01:38:14 volumio volumio[976]: SPOTIFY: SPOTIFY VOLUME 100 Jun 02 01:38:14 volumio volumio[976]: SPOTIFY: VOLUMIO VOLUME 86 Jun 02 01:38:14 volumio volumio[976]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 02 01:38:14 volumio volumio[976]: info: Setting Spotify Volume from Volumio: 86 Jun 02 01:38:14 volumio volumio[976]: info: Initializing connection to go-librespot Websocket Jun 02 01:38:14 volumio go-librespot[2258]: time="2025-06-02T01:38:14+07:00" level=debug msg="new websocket client" Jun 02 01:38:14 volumio volumio[976]: info: Connection to go-librespot Websocket established Jun 02 01:38:15 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 02 01:38:15 volumio volumio[976]: info: CorePlayQueue::getTrack 6 Jun 02 01:38:16 volumio volumio[976]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Jun 02 01:38:16 volumio volumio[976]: info: Sending Spotify command with payload to local API: /player/volume Jun 02 01:38:16 volumio go-librespot[2258]: time="2025-06-02T01:38:16+07:00" level=debug msg="update volume to 56360/65535" Jun 02 01:38:16 volumio volumio[976]: info: CoreCommandRouter::volumioPlay Jun 02 01:38:16 volumio volumio[976]: info: CoreStateMachine::play index undefined Jun 02 01:38:16 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 02 01:38:16 volumio volumio[976]: info: CorePlayQueue::getTrack 6 Jun 02 01:38:16 volumio volumio[976]: info: CoreStateMachine::startPlaybackTimer Jun 02 01:38:16 volumio volumio[976]: info: CorePlayQueue::getTrack 6 Jun 02 01:38:16 volumio volumio[976]: info: [1748803096630] ControllerSpotify::clearAddPlayTrack Jun 02 01:38:16 volumio volumio[976]: info: Sending Spotify command with payload to local API: /player/play Jun 02 01:38:16 volumio go-librespot[2258]: time="2025-06-02T01:38:16+07:00" level=debug msg="resolved context of track" uri="spotify:track:0NDMUgq5VLeo7D14NqlfYO" Jun 02 01:38:16 volumio go-librespot[2258]: time="2025-06-02T01:38:16+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0NDMUgq5VLeo7D14NqlfYO" Jun 02 01:38:16 volumio go-librespot[2258]: time="2025-06-02T01:38:16+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0NDMUgq5VLeo7D14NqlfYO" Jun 02 01:38:16 volumio go-librespot[2258]: time="2025-06-02T01:38:16+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 01:38:16 volumio go-librespot[2258]: time="2025-06-02T01:38:16+07:00" level=trace msg="emitting websocket event: will_play" Jun 02 01:38:16 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0NDMUgq5VLeo7D14NqlfYO","play_origin":"go-librespot"}} Jun 02 01:38:16 volumio go-librespot[2258]: time="2025-06-02T01:38:16+07:00" level=debug msg="selected format OGG_VORBIS_320 (6963649e4805d382de6e9f5e90f24cc352e44424)" uri="spotify:track:0NDMUgq5VLeo7D14NqlfYO" Jun 02 01:38:16 volumio go-librespot[2258]: time="2025-06-02T01:38:16+07:00" level=debug msg="requested aes key for file 6963649e4805d382de6e9f5e90f24cc352e44424, gid: 0NDMUgq5VLeo7D14NqlfYO" Jun 02 01:38:16 volumio go-librespot[2258]: time="2025-06-02T01:38:16+07:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0NDMUgq5VLeo7D14NqlfYO: failed retrieving audio key: failed retrieving aes key with code 1" Jun 02 01:38:16 volumio volumio[976]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jun 02 01:38:17 volumio go-librespot[2258]: time="2025-06-02T01:38:17+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 02 01:38:17 volumio go-librespot[2258]: time="2025-06-02T01:38:17+07:00" level=trace msg="emitting websocket event: volume" Jun 02 01:38:17 volumio volumio[976]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Jun 02 01:38:17 volumio volumio[976]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Jun 02 01:38:17 volumio volumio[976]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Jun 02 01:38:17 volumio volumio[976]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Jun 02 01:38:17 volumio volumio[976]: info: Getting Spotify volume Jun 02 01:38:17 volumio volumio[976]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 02 01:38:17 volumio volumio[976]: info: Spotify volume: 86 Jun 02 01:38:17 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 02 01:38:17 volumio volumio[976]: info: CorePlayQueue::getTrack 6 Jun 02 01:38:17 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jun 02 01:38:18 volumio volumio[976]: info: CoreCommandRouter::volumioNext Jun 02 01:38:18 volumio volumio[976]: info: CoreStateMachine::next Jun 02 01:38:18 volumio volumio[976]: info: CoreStateMachine::stop Jun 02 01:38:18 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 02 01:38:18 volumio volumio[976]: info: CoreStateMachine::play index undefined Jun 02 01:38:18 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 02 01:38:18 volumio volumio[976]: info: CorePlayQueue::getTrack 7 Jun 02 01:38:18 volumio volumio[976]: info: CoreStateMachine::startPlaybackTimer Jun 02 01:38:18 volumio volumio[976]: info: CorePlayQueue::getTrack 7 Jun 02 01:38:18 volumio volumio[976]: info: [1748803098139] ControllerSpotify::clearAddPlayTrack Jun 02 01:38:18 volumio volumio[976]: info: Sending Spotify command with payload to local API: /player/play Jun 02 01:38:18 volumio volumio[976]: info: CoreStateMachine::updateTrackBlock Jun 02 01:38:18 volumio volumio[976]: info: CorePlayQueue::getTrackBlock Jun 02 01:38:18 volumio go-librespot[2258]: time="2025-06-02T01:38:18+07:00" level=debug msg="resolved context of track" uri="spotify:track:6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:18 volumio go-librespot[2258]: time="2025-06-02T01:38:18+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:18 volumio go-librespot[2258]: time="2025-06-02T01:38:18+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:18 volumio go-librespot[2258]: time="2025-06-02T01:38:18+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 01:38:18 volumio go-librespot[2258]: time="2025-06-02T01:38:18+07:00" level=trace msg="emitting websocket event: will_play" Jun 02 01:38:18 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6cc5PzJUddXskJGHJINw9F","play_origin":"go-librespot"}} Jun 02 01:38:18 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6cc5PzJUddXskJGHJINw9F","play_origin":"go-librespot"}} Jun 02 01:38:18 volumio go-librespot[2258]: time="2025-06-02T01:38:18+07:00" level=debug msg="selected format OGG_VORBIS_320 (53298fbc95b76e7d7f6952091acd82318c32b005)" uri="spotify:track:6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:18 volumio go-librespot[2258]: time="2025-06-02T01:38:18+07:00" level=debug msg="requested aes key for file 53298fbc95b76e7d7f6952091acd82318c32b005, gid: 6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:18 volumio go-librespot[2258]: time="2025-06-02T01:38:18+07:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:6cc5PzJUddXskJGHJINw9F: failed retrieving audio key: failed retrieving aes key with code 1" Jun 02 01:38:18 volumio volumio[976]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jun 02 01:38:19 volumio volumio[976]: info: CoreCommandRouter::volumioPlay Jun 02 01:38:19 volumio volumio[976]: info: CoreStateMachine::play index undefined Jun 02 01:38:19 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 02 01:38:19 volumio volumio[976]: info: CorePlayQueue::getTrack 7 Jun 02 01:38:19 volumio volumio[976]: info: CoreStateMachine::startPlaybackTimer Jun 02 01:38:19 volumio volumio[976]: info: CorePlayQueue::getTrack 7 Jun 02 01:38:19 volumio volumio[976]: info: [1748803099106] ControllerSpotify::clearAddPlayTrack Jun 02 01:38:19 volumio volumio[976]: info: Sending Spotify command with payload to local API: /player/play Jun 02 01:38:19 volumio go-librespot[2258]: time="2025-06-02T01:38:19+07:00" level=debug msg="resolved context of track" uri="spotify:track:6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:19 volumio go-librespot[2258]: time="2025-06-02T01:38:19+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:19 volumio go-librespot[2258]: time="2025-06-02T01:38:19+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:19 volumio go-librespot[2258]: time="2025-06-02T01:38:19+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 01:38:19 volumio go-librespot[2258]: time="2025-06-02T01:38:19+07:00" level=trace msg="emitting websocket event: will_play" Jun 02 01:38:19 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6cc5PzJUddXskJGHJINw9F","play_origin":"go-librespot"}} Jun 02 01:38:19 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6cc5PzJUddXskJGHJINw9F","play_origin":"go-librespot"}} Jun 02 01:38:19 volumio go-librespot[2258]: time="2025-06-02T01:38:19+07:00" level=debug msg="selected format OGG_VORBIS_320 (53298fbc95b76e7d7f6952091acd82318c32b005)" uri="spotify:track:6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:19 volumio go-librespot[2258]: time="2025-06-02T01:38:19+07:00" level=debug msg="requested aes key for file 53298fbc95b76e7d7f6952091acd82318c32b005, gid: 6cc5PzJUddXskJGHJINw9F" Jun 02 01:38:19 volumio go-librespot[2258]: time="2025-06-02T01:38:19+07:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:6cc5PzJUddXskJGHJINw9F: failed retrieving audio key: failed retrieving aes key with code 1" Jun 02 01:38:19 volumio volumio[976]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jun 02 01:38:21 volumio volumio[976]: info: Preload queue cleared Jun 02 01:38:21 volumio volumio[976]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::ClearQueue Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::stop Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::clearPlayQueue Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::saveQueue Jun 02 01:38:21 volumio volumio[976]: info: CoreCommandRouter::volumioPushQueue Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::addQueueItems Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::addQueueItems Jun 02 01:38:21 volumio volumio[976]: info: Preload queue cleared Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3y66li7DIrH7HLKIZzxR5H Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3y66li7DIrH7HLKIZzxR5H Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5WkuMbkHX7yR7nnBKCn7tV Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5WkuMbkHX7yR7nnBKCn7tV Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1DVYafsLmcQySKkJnY4RCs Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1DVYafsLmcQySKkJnY4RCs Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3Ids3RXurYBgySph53qWnB Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3Ids3RXurYBgySph53qWnB Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:4sUO0zmF9LZL1XNe1LjHvV Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:4sUO0zmF9LZL1XNe1LjHvV Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0QIBqBajZLLcWfL6mpVsN3 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0QIBqBajZLLcWfL6mpVsN3 Jun 02 01:38:21 volumio volumio[976]: info: CoreCommandRouter::volumioPushQueue Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::saveQueue Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::updateTrackBlock Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::getTrackBlock Jun 02 01:38:21 volumio volumio[976]: info: CoreCommandRouter::volumioPlay Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::play index 5 Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::addQueueItems Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::addQueueItems Jun 02 01:38:21 volumio volumio[976]: info: Preload queue cleared Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0NDMUgq5VLeo7D14NqlfYO Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0NDMUgq5VLeo7D14NqlfYO Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:6cc5PzJUddXskJGHJINw9F Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:6cc5PzJUddXskJGHJINw9F Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5XfGQZA0ioQAWUjlyJRcHc Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5XfGQZA0ioQAWUjlyJRcHc Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:36fgG6NiEuQXznNgf5y2Ck Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:36fgG6NiEuQXznNgf5y2Ck Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3uT8QfoX0BE8ZJa4h98LDW Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3uT8QfoX0BE8ZJa4h98LDW Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:4fj4Jn4nw8fGX8xdbCntJf Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:4fj4Jn4nw8fGX8xdbCntJf Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:7CuYlxVy87LrB2pQOP6i9z Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:7CuYlxVy87LrB2pQOP6i9z Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0s7RyyUlQfd8mnnboHe18n Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0s7RyyUlQfd8mnnboHe18n Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:64PCybDxes3edHijrcsPV4 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:64PCybDxes3edHijrcsPV4 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5gb7vv04eAuLtTlETODPo4 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5gb7vv04eAuLtTlETODPo4 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2k6iN3YG0R1uIWIhY4GsH9 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2k6iN3YG0R1uIWIhY4GsH9 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1LxaXT8hwdBWSNpOqTjF8R Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1LxaXT8hwdBWSNpOqTjF8R Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5VXtBT4iERn7fJWDf5d6Vm Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5VXtBT4iERn7fJWDf5d6Vm Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1xoadYaxtOp9gHDwgmPDuz Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1xoadYaxtOp9gHDwgmPDuz Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:6f7M5UzYYeLFCMIBQhxk2J Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:6f7M5UzYYeLFCMIBQhxk2J Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0e6fZkLArSmDIHnZcIua7t Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0e6fZkLArSmDIHnZcIua7t Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:498g7npirihKT5MPdVSfb0 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:498g7npirihKT5MPdVSfb0 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0lYtIvI7bO51PZSeK22Mbz Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0lYtIvI7bO51PZSeK22Mbz Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0669gFIK8dYK9GGQ0K0QNF Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0669gFIK8dYK9GGQ0K0QNF Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:49kZuPsl8pXRJJGHmwRuW7 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:49kZuPsl8pXRJJGHmwRuW7 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3DLtPObflLQBodZN8qGODT Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3DLtPObflLQBodZN8qGODT Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:4Gs3MrfMQub2r90VWmcnMZ Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:4Gs3MrfMQub2r90VWmcnMZ Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2Pwou3Q2Cf59RxdX2V6MgV Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2Pwou3Q2Cf59RxdX2V6MgV Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:226ljdOTLM2clGpm4mZvAm Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:226ljdOTLM2clGpm4mZvAm Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:6kCU6i8iRrAAmJJ8Sj4JYC Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:6kCU6i8iRrAAmJJ8Sj4JYC Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:7zJ6yuuOnjjRqbKv1zfCAl Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:7zJ6yuuOnjjRqbKv1zfCAl Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2pm7K14nHj2fLrpU8j9bit Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2pm7K14nHj2fLrpU8j9bit Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:6mKMGpkgP2cH5gmqILWe7b Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:6mKMGpkgP2cH5gmqILWe7b Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1KZVA4mJbjH6V9i7lP36FH Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1KZVA4mJbjH6V9i7lP36FH Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:72NMPuJCRsOUoXQJdzVfdo Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:72NMPuJCRsOUoXQJdzVfdo Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3Alwi53Ahc2GwHgvel42b2 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3Alwi53Ahc2GwHgvel42b2 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5oFEvbM7lGnx8jfAkuhVyo Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5oFEvbM7lGnx8jfAkuhVyo Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2qWP5ZarXRsdmxzz3L3BtP Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2qWP5ZarXRsdmxzz3L3BtP Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:26zqmmkqUK6mCc87XDzPym Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:26zqmmkqUK6mCc87XDzPym Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3COYA2vgfcUhDyRlVpZy5p Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3COYA2vgfcUhDyRlVpZy5p Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:75weJdjMaaF016Df8BNl0f Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:75weJdjMaaF016Df8BNl0f Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:31VNCmwspR7nVJ6kruUuJt Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:31VNCmwspR7nVJ6kruUuJt Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0NKYhzHVkjRXipH1hFC5xT Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0NKYhzHVkjRXipH1hFC5xT Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:78lw4wahFNotXb0mOEtPkM Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:78lw4wahFNotXb0mOEtPkM Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5bOh5gwwjMQfMwgusZS78M Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5bOh5gwwjMQfMwgusZS78M Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:37uug3gaq86yvFTjV6WkaV Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:37uug3gaq86yvFTjV6WkaV Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:6xKs4CnVadRzdNZ48vhT27 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:6xKs4CnVadRzdNZ48vhT27 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2a5hng9yXtbjtTVVm9UviC Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2a5hng9yXtbjtTVVm9UviC Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0pkKpktoYIYzVMH5AGrdc8 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0pkKpktoYIYzVMH5AGrdc8 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5kJMW3pK49PvQDtpVryHf5 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5kJMW3pK49PvQDtpVryHf5 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1DFmBjoeQN9DpOVTEewyx0 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1DFmBjoeQN9DpOVTEewyx0 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:142PiXzA84lmEw2RstFHFa Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:142PiXzA84lmEw2RstFHFa Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2TOEn8TnvwiQgwZdqVtfH5 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2TOEn8TnvwiQgwZdqVtfH5 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2RdEC8Ff83WkX7kDVCHseE Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2RdEC8Ff83WkX7kDVCHseE Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3K7RddI2L8Wiv7uIbrhfLc Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3K7RddI2L8Wiv7uIbrhfLc Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:6PJ4rafx2ufoaPaTewsRfh Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:6PJ4rafx2ufoaPaTewsRfh Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:40pWxpbXoBYGPCiofujjZ6 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:40pWxpbXoBYGPCiofujjZ6 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2xOhv7XudrBDtkID1jwsFE Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2xOhv7XudrBDtkID1jwsFE Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:7watgqoaISZV15DH0OZa4m Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:7watgqoaISZV15DH0OZa4m Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3c8s2bCBk3cn8Taete6Q5B Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3c8s2bCBk3cn8Taete6Q5B Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5IZDnmnMBzLnE6APoYL26d Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5IZDnmnMBzLnE6APoYL26d Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:4CUvVaAYuXtvYURLFz7EIL Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:4CUvVaAYuXtvYURLFz7EIL Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0kHgteR4TV4LO80wrasDSR Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0kHgteR4TV4LO80wrasDSR Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1W4dKR6vz6LxhRtMTl9fPx Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1W4dKR6vz6LxhRtMTl9fPx Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3hjirCdXFnVJDZsXlOfhfd Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3hjirCdXFnVJDZsXlOfhfd Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:4rIBbB1vt0lEKDG2UTmfP0 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:4rIBbB1vt0lEKDG2UTmfP0 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:4NTanSVXBkQ2NmDEbr2vLE Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:4NTanSVXBkQ2NmDEbr2vLE Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3hqOrxH5qPlvrApcb7Ac8c Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3hqOrxH5qPlvrApcb7Ac8c Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5YiqPAVbiFUj1G1qvbXo0X Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5YiqPAVbiFUj1G1qvbXo0X Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:6kDcfNV4jAz7izU56ZxlDm Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:6kDcfNV4jAz7izU56ZxlDm Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2e6uyFP80Vuaz7V7bDWD0e Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2e6uyFP80Vuaz7V7bDWD0e Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3YctJXK6kznnWl68TnYobN Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3YctJXK6kznnWl68TnYobN Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0bAmqokpYHnFWAHpzqDOxB Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0bAmqokpYHnFWAHpzqDOxB Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1K0HQ30Wc11okzlcnFA7Ub Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1K0HQ30Wc11okzlcnFA7Ub Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:7sZgr8RsXkDwkmiQok691a Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:7sZgr8RsXkDwkmiQok691a Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3A9A7mfVDVm3rrS9SMGhg5 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3A9A7mfVDVm3rrS9SMGhg5 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3Ndroo5HpBKKTRGYReAYHM Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3Ndroo5HpBKKTRGYReAYHM Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1izPmgSW7FV6XFdEOiTvOY Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1izPmgSW7FV6XFdEOiTvOY Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:354swDEk1Zdo9y57fEqmRg Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:354swDEk1Zdo9y57fEqmRg Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5LQpQ6SDeaz6SIkR0lvsoC Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5LQpQ6SDeaz6SIkR0lvsoC Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:11hcyWq7qSwBE3bvv5Ialn Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:11hcyWq7qSwBE3bvv5Ialn Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:64uzIqhEOq1veSVO03Ux7D Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:64uzIqhEOq1veSVO03Ux7D Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:55Eo6NDkVhSRBonrT16kXM Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:55Eo6NDkVhSRBonrT16kXM Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1ahMIChLwnLRGDu5AhMWZI Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1ahMIChLwnLRGDu5AhMWZI Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2JuHIbFudHwDqQssgqsH3i Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2JuHIbFudHwDqQssgqsH3i Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0A0oqleZkyD8FN6aW48Jzn Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0A0oqleZkyD8FN6aW48Jzn Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3Vo5KWON7ii5Cs6gAivUWH Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3Vo5KWON7ii5Cs6gAivUWH Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1o6cYDMHvKOfizi4d9Lqxr Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1o6cYDMHvKOfizi4d9Lqxr Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:7Cjsw965r7mVK888ZqP6Wo Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:7Cjsw965r7mVK888ZqP6Wo Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1J12HjUuXfJnaUdubTEzSR Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1J12HjUuXfJnaUdubTEzSR Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5PGh9MyKry8slG5AfvD1eD Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5PGh9MyKry8slG5AfvD1eD Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:4WZf4gJ2MvBec6XPdUiqcq Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:4WZf4gJ2MvBec6XPdUiqcq Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2uZmeuNAxSm7XfVIwLkhCx Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2uZmeuNAxSm7XfVIwLkhCx Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:3ZbZtdEw9U0uZW4tZItIwq Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:3ZbZtdEw9U0uZW4tZItIwq Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0HAfl1uPBf5qTMiuAi6Ym7 Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0HAfl1uPBf5qTMiuAi6Ym7 Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:2EG7LIDGxjvw0J363cAgwo Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:2EG7LIDGxjvw0J363cAgwo Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:0oSc7X1uRQGuEqNRtXEeQL Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:0oSc7X1uRQGuEqNRtXEeQL Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:5NWkYMp7RhANkoJqk3ZBGh Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:5NWkYMp7RhANkoJqk3ZBGh Jun 02 01:38:21 volumio volumio[976]: info: Adding Item to queue: spotify:track:1XZE0InCx3SdCnLpVsPpZl Jun 02 01:38:21 volumio volumio[976]: info: Using cached record of: spotify:track:1XZE0InCx3SdCnLpVsPpZl Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::stop Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 02 01:38:21 volumio volumio[976]: info: CoreCommandRouter::volumioPushQueue Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::saveQueue Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::play index undefined Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::updateTrackBlock Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::getTrackBlock Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::getTrack 5 Jun 02 01:38:21 volumio volumio[976]: info: CoreStateMachine::startPlaybackTimer Jun 02 01:38:21 volumio volumio[976]: info: CorePlayQueue::getTrack 5 Jun 02 01:38:21 volumio volumio[976]: info: [1748803101759] ControllerSpotify::clearAddPlayTrack Jun 02 01:38:21 volumio volumio[976]: info: Sending Spotify command with payload to local API: /player/play Jun 02 01:38:21 volumio go-librespot[2258]: time="2025-06-02T01:38:21+07:00" level=debug msg="resolved context of track" uri="spotify:track:0QIBqBajZLLcWfL6mpVsN3" Jun 02 01:38:21 volumio go-librespot[2258]: time="2025-06-02T01:38:21+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0QIBqBajZLLcWfL6mpVsN3" Jun 02 01:38:21 volumio go-librespot[2258]: time="2025-06-02T01:38:21+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0QIBqBajZLLcWfL6mpVsN3" Jun 02 01:38:21 volumio go-librespot[2258]: time="2025-06-02T01:38:21+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 02 01:38:21 volumio go-librespot[2258]: time="2025-06-02T01:38:21+07:00" level=trace msg="emitting websocket event: will_play" Jun 02 01:38:21 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0QIBqBajZLLcWfL6mpVsN3","play_origin":"go-librespot"}} Jun 02 01:38:21 volumio go-librespot[2258]: time="2025-06-02T01:38:21+07:00" level=debug msg="selected format OGG_VORBIS_320 (ebc55d7908f513eb0c23e658c5ff4b8b3a1f340d)" uri="spotify:track:0QIBqBajZLLcWfL6mpVsN3" Jun 02 01:38:21 volumio go-librespot[2258]: time="2025-06-02T01:38:21+07:00" level=debug msg="requested aes key for file ebc55d7908f513eb0c23e658c5ff4b8b3a1f340d, gid: 0QIBqBajZLLcWfL6mpVsN3" Jun 02 01:38:22 volumio go-librespot[2258]: time="2025-06-02T01:38:22+07:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0QIBqBajZLLcWfL6mpVsN3: failed retrieving audio key: failed retrieving aes key with code 1" Jun 02 01:38:22 volumio volumio[976]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jun 02 01:38:23 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 02 01:38:23 volumio volumio[976]: info: CorePlayQueue::getTrack 5 Jun 02 01:38:39 volumio go-librespot[2258]: time="2025-06-02T01:38:39+07:00" level=trace msg="sent dealer ping" Jun 02 01:38:39 volumio go-librespot[2258]: time="2025-06-02T01:38:39+07:00" level=trace msg="received dealer pong" Jun 02 01:38:41 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jun 02 01:38:41 volumio volumio[976]: info: CURURI: artists:// Jun 02 01:38:41 volumio volumio[976]: info: Preload queue cleared Jun 02 01:38:45 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 02 01:38:45 volumio volumio[976]: info: Preload queue cleared Jun 02 01:38:46 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 02 01:38:47 volumio volumio[976]: info: Preload queue cleared Jun 02 01:38:51 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 02 01:38:51 volumio volumio[976]: info: Preload queue cleared Jun 02 01:38:57 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 02 01:38:57 volumio volumio[976]: info: Preload queue cleared Jun 02 01:38:58 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 02 01:38:58 volumio volumio[976]: info: Preload queue cleared Jun 02 01:39:00 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 02 01:39:00 volumio volumio[976]: info: Preload queue cleared Jun 02 01:39:05 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 02 01:39:05 volumio volumio[976]: info: Preload queue cleared Jun 02 01:39:08 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 02 01:39:08 volumio volumio[976]: info: Preload queue cleared Jun 02 01:39:09 volumio go-librespot[2258]: time="2025-06-02T01:39:09+07:00" level=trace msg="sent dealer ping" Jun 02 01:39:09 volumio go-librespot[2258]: time="2025-06-02T01:39:09+07:00" level=trace msg="received dealer pong" Jun 02 01:39:10 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 02 01:39:10 volumio volumio[976]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 01:39:10 volumio volumio[976]: TypeError: Cannot read property 'length' of undefined Jun 02 01:39:10 volumio volumio[976]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Jun 02 01:39:10 volumio volumio[976]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Jun 02 01:39:10 volumio volumio[976]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Jun 02 01:39:10 volumio volumio[976]: at Parser.emit (events.js:315:20) Jun 02 01:39:10 volumio volumio[976]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Jun 02 01:39:10 volumio volumio[976]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Jun 02 01:39:10 volumio volumio[976]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Jun 02 01:39:10 volumio volumio[976]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Jun 02 01:39:10 volumio volumio[976]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Jun 02 01:39:10 volumio volumio[976]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Jun 02 01:39:10 volumio volumio[976]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Jun 02 01:39:10 volumio volumio[976]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Jun 02 01:39:10 volumio volumio[976]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Jun 02 01:39:10 volumio volumio[976]: at IncomingMessage.emit (events.js:327:22) Jun 02 01:39:10 volumio volumio[976]: at endReadableNT (internal/streams/readable.js:1327:12) Jun 02 01:39:10 volumio volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jun 02 01:39:10 volumio volumio[976]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 02 01:39:10 volumio sudo[2413]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-02 01:38 Jun 02 01:39:10 volumio sudo[2413]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"