Oct 11 11:47:02 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 11 11:47:05 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Oct 11 11:47:05 parus volumio[1144]: info: In handleBrowseUri, curUri=spotify/myalbums Oct 11 11:47:07 parus volumio[1144]: info: Preload queue cleared Oct 11 11:47:09 parus volumio[1144]: info: Preload queue cleared Oct 11 11:47:09 parus volumio[1144]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 11 11:47:09 parus volumio[1144]: info: CoreStateMachine::ClearQueue Oct 11 11:47:09 parus volumio[1144]: info: CoreStateMachine::stop Oct 11 11:47:09 parus volumio[1144]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 11:47:09 parus volumio[1144]: info: CorePlayQueue::clearPlayQueue Oct 11 11:47:09 parus volumio[1144]: info: CorePlayQueue::saveQueue Oct 11 11:47:09 parus volumio[1144]: info: CoreCommandRouter::volumioPushQueue Oct 11 11:47:09 parus volumio[1144]: info: CoreStateMachine::addQueueItems Oct 11 11:47:09 parus volumio[1144]: info: CorePlayQueue::addQueueItems Oct 11 11:47:09 parus volumio[1144]: info: Preload queue cleared Oct 11 11:47:09 parus volumio[1144]: info: Adding Item to queue: spotify:album:0VygHkFjTH3wretFel2qJ1 Oct 11 11:47:09 parus volumio[1144]: info: Exploding uri spotify:album:0VygHkFjTH3wretFel2qJ1 in service spop Oct 11 11:47:09 parus volumio[1144]: SPOTIFY: EXPLODING URI:spotify:album:0VygHkFjTH3wretFel2qJ1 Oct 11 11:47:10 parus volumio[1144]: info: CoreCommandRouter::volumioPushQueue Oct 11 11:47:10 parus volumio[1144]: info: CorePlayQueue::saveQueue Oct 11 11:47:10 parus volumio[1144]: info: CoreStateMachine::updateTrackBlock Oct 11 11:47:10 parus volumio[1144]: info: CorePlayQueue::getTrackBlock Oct 11 11:47:10 parus volumio[1144]: info: CoreCommandRouter::volumioPlay Oct 11 11:47:10 parus volumio[1144]: info: CoreStateMachine::play index 0 Oct 11 11:47:10 parus volumio[1144]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 11:47:10 parus volumio[1144]: info: CoreStateMachine::stop Oct 11 11:47:10 parus volumio[1144]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 11:47:10 parus volumio[1144]: info: CoreStateMachine::play index undefined Oct 11 11:47:10 parus volumio[1144]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 11:47:10 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:47:10 parus volumio[1144]: info: CoreStateMachine::startPlaybackTimer Oct 11 11:47:10 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:47:10 parus volumio[1144]: info: [1791712030079] ControllerSpotify::clearAddPlayTrack Oct 11 11:47:10 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 11 11:47:10 parus volumio[1144]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 11 11:47:10 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 11 11:47:10 parus volumio[1144]: info: Received Get System Version Oct 11 11:47:10 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 11 11:47:10 parus volumio[1144]: info: Received Get System Info Oct 11 11:47:10 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 11 11:47:10 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 11 11:47:10 parus volumio[1144]: info: Discovery: Getting this device information Oct 11 11:47:10 parus volumio[1144]: info: CoreCommandRouter::volumioGetState Oct 11 11:47:10 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:47:10 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 11 11:47:11 parus volumio[1144]: error: Failed to read Spotify local API status: Error: Response timeout of 1500ms exceeded Oct 11 11:47:11 parus volumio[1144]: error: Aborting Spotify playback: go-librespot has no active session Oct 11 11:47:11 parus volumio[1144]: info: CoreStateMachine::stPlaybackTimer Oct 11 11:47:11 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:47:11 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:47:11 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:47:11 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:47:11 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:47:11 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:47:11 parus volumio[1144]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:47:11 parus volumio[1144]: verbose: CURRENT POSITION 0 Oct 11 11:47:11 parus volumio[1144]: info: CoreStateMachine::syncState stateService stop Oct 11 11:47:11 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus stop Oct 11 11:47:11 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:47:11 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:47:11 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:47:11 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:47:11 parus volumio[1144]: info: No code Oct 11 11:47:11 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:47:11 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:47:11 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:47:14 parus systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 11 11:47:17 parus systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 11 11:47:17 parus systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 11 11:47:17 parus systemd[1]: setdatetime-helper.service: Consumed 1.079s CPU time. Oct 11 11:47:25 parus volumio[1144]: info: CoreCommandRouter::volumioGetState Oct 11 11:47:25 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:47:27 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 11 11:47:27 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 11 11:47:30 parus volumio[1144]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 11 11:47:51 parus go-librespot[5127]: time="2026-10-11T11:47:51+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 11 11:47:51 parus go-librespot[5127]: time="2026-10-11T11:47:51+02:00" level=debug msg="completed keyexchange" Oct 11 11:47:51 parus go-librespot[5127]: time="2026-10-11T11:47:51+02:00" level=debug msg="completed challenge" Oct 11 11:47:51 parus go-librespot[5127]: time="2026-10-11T11:47:51+02:00" level=info msg="authenticated AP" username="11******78" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=info msg="authenticated Login5" username="11******78" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="stored credentials" username="11******78" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="initializing zeroconf session" username="11******78" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="connected to gew4-dealer.spotify.com:443" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=trace msg="starting accesspoint recv loop" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=trace msg="starting dealer recv loop" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 11 11:47:52 parus volumio[1144]: info: Spotify volume: 100 Oct 11 11:47:52 parus volumio[1144]: info: Spotify volume: 100 Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="received connection id: ZmI1ODc5YTktMmU1...N0Y3OTkyOTg2OA==" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=trace msg="emitting websocket event: playback_ready" Oct 11 11:47:52 parus go-librespot[5127]: time="2026-10-11T11:47:52+02:00" level=debug msg="update volume requested to 65535/65535" Oct 11 11:47:52 parus volumio[1144]: SPOTIFY: received: {"type":"playback_ready","data":null} Oct 11 11:47:52 parus volumio[1144]: error: Failed to decode event: playback_ready Oct 11 11:47:52 parus volumio[1144]: SPOTIFY: received: {"type":"playback_ready","data":null} Oct 11 11:47:52 parus volumio[1144]: error: Failed to decode event: playback_ready Oct 11 11:47:53 parus go-librespot[5127]: time="2026-10-11T11:47:53+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 11 11:47:53 parus go-librespot[5127]: time="2026-10-11T11:47:53+02:00" level=trace msg="emitting websocket event: volume" Oct 11 11:47:53 parus volumio[1144]: SPOTIFY: received: {"type":"volume","data":{"max":100,"value":100}} Oct 11 11:47:53 parus volumio[1144]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Oct 11 11:47:53 parus volumio[1144]: info: Setting Volumio Volume from Spotify: 100 Oct 11 11:47:53 parus volumio[1144]: info: VolumeController::SetAlsaVolume100 Oct 11 11:47:53 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:47:53 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:47:53 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:47:53 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:47:53 parus volumio[1144]: SPOTIFY: received: {"type":"volume","data":{"max":100,"value":100}} Oct 11 11:47:53 parus volumio[1144]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Oct 11 11:48:00 parus volumio[1144]: info: CoreCommandRouter::volumioGetState Oct 11 11:48:00 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:00 parus volumio[1144]: info: CoreCommandRouter::volumioPlay Oct 11 11:48:00 parus volumio[1144]: info: CoreStateMachine::play index undefined Oct 11 11:48:00 parus volumio[1144]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 11:48:00 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:00 parus volumio[1144]: info: CoreStateMachine::startPlaybackTimer Oct 11 11:48:00 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:00 parus volumio[1144]: info: [1791712080307] ControllerSpotify::clearAddPlayTrack Oct 11 11:48:00 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:00 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:00 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d0000b27364cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","seek":0,"duration":8,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:00 parus volumio[1144]: verbose: CURRENT POSITION 0 Oct 11 11:48:00 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:00 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus stop Oct 11 11:48:00 parus volumio[1144]: info: Sending Spotify command with payload to local API: /player/play Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=debug msg="resolved context of track" uri="spotify:track:1exydvdEsKSO232oyncHkE" Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1exydvdEsKSO232oyncHkE" Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1exydvdEsKSO232oyncHkE" Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=trace msg="emitting websocket event: will_play" Oct 11 11:48:00 parus volumio[1144]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1exydvdEsKSO232oyncHkE","uri":"spotify:track:1exydvdEsKSO232oyncHkE","play_origin":"go-librespot"}} Oct 11 11:48:00 parus volumio[1144]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:1exydvdEsKSO232oyncHkE","uri":"spotify:track:1exydvdEsKSO232oyncHkE","play_origin":"go-librespot"}} Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 433" Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=debug msg="selected format OGG_VORBIS_320 (7580e3b9971ed7601be40ffb5eec6587888fb6fd)" uri="spotify:track:1exydvdEsKSO232oyncHkE" Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=debug msg="requested aes key for file 7580e3b9971ed7601be40ffb5eec6587888fb6fd, gid: 1exydvdEsKSO232oyncHkE" Oct 11 11:48:00 parus go-librespot[5127]: time="2026-10-11T11:48:00+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1exydvdEsKSO232oyncHkE" Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02:00" level=debug msg="fetched first chunk of 1, total size is 349964 bytes" uri="spotify:track:1exydvdEsKSO232oyncHkE" Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02:00" level=debug msg="track has no narration" uri="spotify:track:1exydvdEsKSO232oyncHkE" Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02:00" level=debug msg="created new output device" Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02: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, PCM format = FLOAT_LE" Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02:00" level=info msg="loaded track \"633 Jesu fåglar\" (paused: false, position: 0ms, duration: 8173ms, prefetched: false)" uri="spotify:track:1exydvdEsKSO232oyncHkE" Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02:00" level=trace msg="prefetch as soon as possible" Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02:00" level=trace msg="emitting websocket event: metadata" Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02:00" level=trace msg="emitting websocket event: playing" Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: received: {"type":"metadata","data":{"album_cover_url":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","album_name":"Hard n' Horny","artist_names":["Wigwam"],"bit_depth":null,"bitrate":320,"codec":"vorbis","disc_number":1,"duration":8173,"format":"OGG_VORBIS_320","name":"633 Jesu fåglar","position":0,"release_date":"year:1969","sample_rate":44100,"track_number":1,"uri":"spotify:track:1exydvdEsKSO232oyncHkE"}} Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:1exydvdEsKSO232oyncHkE","uri":"spotify:track:1exydvdEsKSO232oyncHkE","resume":false,"play_origin":"go-librespot"}} Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: {"status":"play","service":"spop","title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","seek":0,"duration":8,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","seek":0,"duration":8,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:02 parus volumio[1144]: verbose: CURRENT POSITION 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:48:02 parus volumio[1144]: info: Received an update from plugin. extracting info from payload Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: received: {"type":"metadata","data":{"album_cover_url":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","album_name":"Hard n' Horny","artist_names":["Wigwam"],"bit_depth":null,"bitrate":320,"codec":"vorbis","disc_number":1,"duration":8173,"format":"OGG_VORBIS_320","name":"633 Jesu fåglar","position":0,"release_date":"year:1969","sample_rate":44100,"track_number":1,"uri":"spotify:track:1exydvdEsKSO232oyncHkE"}} Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:1exydvdEsKSO232oyncHkE","uri":"spotify:track:1exydvdEsKSO232oyncHkE","resume":false,"play_origin":"go-librespot"}} Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: {"status":"play","service":"spop","title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","seek":0,"duration":8,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","seek":0,"duration":8,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:02 parus volumio[1144]: verbose: CURRENT POSITION 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:48:02 parus volumio[1144]: info: Received an update from plugin. extracting info from payload Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:02 parus go-librespot[5127]: time="2026-10-11T11:48:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: {"status":"play","service":"spop","title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","seek":0,"duration":8,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","seek":0,"duration":8,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:02 parus volumio[1144]: verbose: CURRENT POSITION 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:48:02 parus volumio[1144]: info: Received an update from plugin. extracting info from payload Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:02 parus volumio[1144]: SPOTIFY: {"status":"play","service":"spop","title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","seek":0,"duration":8,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","seek":0,"duration":8,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:02 parus volumio[1144]: verbose: CURRENT POSITION 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:48:02 parus volumio[1144]: info: Received an update from plugin. extracting info from payload Oct 11 11:48:02 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:02 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:02 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:03 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:03 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:03 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:05 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:05 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:05 parus volumio[1144]: info: Prefetching next song Oct 11 11:48:05 parus volumio[1144]: info: [1791712085818] ControllerSpotify::prefetch Oct 11 11:48:05 parus volumio[1144]: info: Sending Spotify command with payload to local API: /player/add_to_queue Oct 11 11:48:06 parus go-librespot[5127]: time="2026-10-11T11:48:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 11:48:06 parus go-librespot[5127]: time="2026-10-11T11:48:06+02:00" level=trace msg="prefetch as soon as possible" Oct 11 11:48:06 parus go-librespot[5127]: time="2026-10-11T11:48:06+02:00" level=debug msg="prefetching next track" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:06 parus go-librespot[5127]: time="2026-10-11T11:48:06+02:00" level=debug msg="selected format OGG_VORBIS_320 (dd867697e2626385d7050a01093bf7810f4efa7f)" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:06 parus go-librespot[5127]: time="2026-10-11T11:48:06+02:00" level=debug msg="requested aes key for file dd867697e2626385d7050a01093bf7810f4efa7f, gid: 72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:06 parus go-librespot[5127]: time="2026-10-11T11:48:06+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:06 parus volumio[1144]: info: CoreCommandRouter::volumioNext Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::next Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::stop Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::stPlaybackTimer Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::updateTrackBlock Oct 11 11:48:06 parus volumio[1144]: info: CorePlayQueue::getTrackBlock Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:06 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:06 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:48:06 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::serviceStop Oct 11 11:48:06 parus volumio[1144]: info: CorePlayQueue::getTrack 0 Oct 11 11:48:06 parus volumio[1144]: info: CoreCommandRouter::serviceStop Oct 11 11:48:06 parus volumio[1144]: info: Spotify Stop Oct 11 11:48:06 parus volumio[1144]: SPOTIFY: SPOTIFY STOP Oct 11 11:48:06 parus volumio[1144]: SPOTIFY: {"status":"play","position":0,"title":"633 Jesu fåglar","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d0000b27364cec23f4e5441ad807580fa","uri":"spotify:track:1exydvdEsKSO232oyncHkE","trackType":"spotify","codec":"ogg","seek":0,"duration":8,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Oct 11 11:48:06 parus volumio[1144]: info: Sending Spotify command to local API: /player/pause Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::play index undefined Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 11 11:48:06 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::startPlaybackTimer Oct 11 11:48:06 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:06 parus volumio[1144]: info: [1791712086914] ControllerSpotify::clearAddPlayTrack Oct 11 11:48:06 parus volumio[1144]: info: CoreStateMachine::updateTrackBlock Oct 11 11:48:06 parus volumio[1144]: info: CorePlayQueue::getTrackBlock Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="fetched first chunk of 27, total size is 13892452 bytes" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=info msg="prefetched track \"Pidän sinusta\" (duration: 338240ms)" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="pause track at 4844ms" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=trace msg="emitting websocket event: paused" Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:1exydvdEsKSO232oyncHkE","uri":"spotify:track:1exydvdEsKSO232oyncHkE","play_origin":"go-librespot"}} Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: verbose: CURRENT POSITION 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState stateService pause Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus stop Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:1exydvdEsKSO232oyncHkE","uri":"spotify:track:1exydvdEsKSO232oyncHkE","play_origin":"go-librespot"}} Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: verbose: CURRENT POSITION 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState stateService pause Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus stop Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d0000b27364cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":0,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: verbose: CURRENT POSITION 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus stop Oct 11 11:48:07 parus volumio[1144]: info: Sending Spotify command with payload to local API: /player/play Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="fetched chunk 1/26, size: 524288" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="resolved context of track" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=trace msg="emitting websocket event: will_play" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="track has no narration" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","play_origin":"go-librespot"}} Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","play_origin":"go-librespot"}} Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02: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, PCM format = FLOAT_LE" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=info msg="loaded track \"Pidän sinusta\" (paused: false, position: 0ms, duration: 338240ms, prefetched: true)" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=trace msg="scheduling prefetch in 308s" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=trace msg="emitting websocket event: metadata" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=trace msg="emitting websocket event: playing" Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: received: {"type":"metadata","data":{"album_cover_url":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","album_name":"Hard n' Horny","artist_names":["Wigwam"],"bit_depth":null,"bitrate":320,"codec":"vorbis","disc_number":1,"duration":338240,"format":"OGG_VORBIS_320","name":"Pidän sinusta","position":0,"release_date":"year:1969","sample_rate":44100,"track_number":2,"uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm"}} Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","resume":false,"play_origin":"go-librespot"}} Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: {"status":"play","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":0,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":0,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: verbose: CURRENT POSITION 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:48:07 parus volumio[1144]: info: Received an update from plugin. extracting info from payload Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: received: {"type":"metadata","data":{"album_cover_url":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","album_name":"Hard n' Horny","artist_names":["Wigwam"],"bit_depth":null,"bitrate":320,"codec":"vorbis","disc_number":1,"duration":338240,"format":"OGG_VORBIS_320","name":"Pidän sinusta","position":0,"release_date":"year:1969","sample_rate":44100,"track_number":2,"uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm"}} Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","resume":false,"play_origin":"go-librespot"}} Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: {"status":"play","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":0,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":0,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: verbose: CURRENT POSITION 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:48:07 parus volumio[1144]: info: Received an update from plugin. extracting info from payload Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="fetched chunk 2/26, size: 524288" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: {"status":"play","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":0,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":0,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: verbose: CURRENT POSITION 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:48:07 parus volumio[1144]: info: Received an update from plugin. extracting info from payload Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:07 parus volumio[1144]: SPOTIFY: {"status":"play","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":0,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":0,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:07 parus volumio[1144]: verbose: CURRENT POSITION 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState stateService play Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus play Oct 11 11:48:07 parus volumio[1144]: info: Received an update from plugin. extracting info from payload Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:07 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:07 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:07 parus go-librespot[5127]: time="2026-10-11T11:48:07+02:00" level=debug msg="fetched chunk 3/26, size: 524288" uri="spotify:track:72kmSs7G3aPNnLa86qfxrm" Oct 11 11:48:08 parus ntpd[902]: CLOCK: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 11 11:48:10 parus volumio[1144]: info: CoreCommandRouter::volumioPause Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::pause Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::stPlaybackTimer Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::servicePause Oct 11 11:48:10 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:10 parus volumio[1144]: info: CoreCommandRouter::servicePause Oct 11 11:48:10 parus volumio[1144]: info: Spotify Received pause Oct 11 11:48:10 parus volumio[1144]: SPOTIFY: SPOTIFY PAUSE Oct 11 11:48:10 parus volumio[1144]: SPOTIFY: {"status":"play","position":1,"title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d0000b27364cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","codec":"ogg","seek":0,"duration":338,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Oct 11 11:48:10 parus volumio[1144]: info: Sending Spotify command to local API: /player/pause Oct 11 11:48:10 parus go-librespot[5127]: time="2026-10-11T11:48:10+02:00" level=debug msg="pause track at 2822ms" Oct 11 11:48:10 parus go-librespot[5127]: time="2026-10-11T11:48:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 11:48:10 parus go-librespot[5127]: time="2026-10-11T11:48:10+02:00" level=trace msg="emitting websocket event: paused" Oct 11 11:48:10 parus volumio[1144]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","play_origin":"go-librespot"}} Oct 11 11:48:10 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:10 parus volumio[1144]: SPOTIFY: {"status":"pause","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":2000,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:10 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:10 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:10 parus volumio[1144]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":2000,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:10 parus volumio[1144]: verbose: CURRENT POSITION 1 Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::syncState stateService pause Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus pause Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:10 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:10 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 11 11:48:10 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::stPlaybackTimer Oct 11 11:48:10 parus volumio[1144]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","play_origin":"go-librespot"}} Oct 11 11:48:10 parus volumio[1144]: SPOTIFY: PUSH STATE SPOTIFY Oct 11 11:48:10 parus volumio[1144]: SPOTIFY: {"status":"pause","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":2000,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:10 parus volumio[1144]: info: CoreCommandRouter::servicePushState Oct 11 11:48:10 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:10 parus volumio[1144]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Pidän sinusta","artist":"Wigwam","album":"Hard n' Horny","albumart":"https://i.scdn.co/image/ab67616d00001e0264cec23f4e5441ad807580fa","uri":"spotify:track:72kmSs7G3aPNnLa86qfxrm","trackType":"spotify","seek":2000,"duration":338,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 11 11:48:10 parus volumio[1144]: verbose: CURRENT POSITION 1 Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::syncState stateService pause Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::syncState currentStatus pause Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::pushState Oct 11 11:48:10 parus volumio[1144]: info: CorePlayQueue::getTrack 1 Oct 11 11:48:10 parus volumio[1144]: info: CoreCommandRouter::volumioPushState Oct 11 11:48:10 parus volumio[1144]: info: CoreStateMachine::stPlaybackTimer Oct 11 11:48:10 parus go-librespot[5127]: time="2026-10-11T11:48:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 11 11:48:19 parus volumio[1144]: info: Retrieving Cloud Streaming UI Oct 11 11:48:19 parus volumio[1144]: info: Getting Tidal Cloud Configuration Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 11 11:48:19 parus volumio[1144]: info: Getting Qobuz Cloud Configuration Oct 11 11:48:19 parus volumio[1144]: info: Asking plugin for UI Config Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 11 11:48:19 parus volumio[1144]: info: Getting Spotify Cloud Configuration Oct 11 11:48:19 parus volumio[1144]: info: Asking plugin for UI Config Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 11 11:48:19 parus volumio[1144]: info: Saving Spotify Acccount Oct 11 11:48:19 parus volumio[1144]: info: Got Tidal Cloud Configuration Oct 11 11:48:19 parus volumio[1144]: info: Got it Oct 11 11:48:19 parus volumio[1144]: info: Got it Oct 11 11:48:19 parus volumio[1144]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 11 11:48:19 parus volumio[1144]: error: Error retrieving Highresaudio conf: TypeError: Cannot read properties of undefined (reading 'onSave') Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::volumioGetBrowseSources Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::volumioGetBrowseSources Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::volumioGetBrowseSources Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 11 11:48:19 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Oct 11 11:48:23 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 11 11:48:25 parus wpa_supplicant[2746]: wlan0: WPA: Group rekeying completed with dc:39:6f:4c:a3:47 [GTK=CCMP] Oct 11 11:48:27 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 11 11:48:31 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 11 11:48:35 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 11 11:48:39 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 11 11:48:42 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: networkfs , discoverShares Oct 11 11:48:42 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , browseForService Oct 11 11:48:43 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 11 11:48:44 parus volumio[1144]: info: Executing SMB command: smbclient --no-pass --debuglevel=0 -L fritz.box. -m SMB3_11 Oct 11 11:48:44 parus volumio[1144]: info: Executing SMB command: smbclient --no-pass --debuglevel=0 -L fritz.box. -m SMB3_11 Oct 11 11:48:44 parus volumio[1144]: info: Executing SMB command: smbclient --no-pass --debuglevel=0 -L NAStradamus.local. -m SMB3_11 Oct 11 11:48:44 parus volumio[1144]: info: Error browsing device 192-168-178-1 for shares: Command failed: smbclient --no-pass --debuglevel=0 -L fritz.box. -m SMB3_11 Oct 11 11:48:44 parus volumio[1144]: info: Error browsing device NAStradamus for shares: Command failed: smbclient --no-pass --debuglevel=0 -L NAStradamus.local. -m SMB3_11 Oct 11 11:48:44 parus volumio[1144]: info: Error browsing device fritz-box for shares: Command failed: smbclient --no-pass --debuglevel=0 -L fritz.box. -m SMB3_11 Oct 11 11:48:47 parus volumio[1144]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 11 11:48:47 parus volumio[1144]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 11 11:48:47 parus volumio[1144]: Error: dns service error: unknown Oct 11 11:48:47 parus volumio[1144]: at MDNSService.on_resolver_done (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:19:30) Oct 11 11:48:47 parus volumio[1144]: at MDNSService.self.watcher.callback (/volumio/node_modules/mdns/lib/mdns_service.js:18:40) { Oct 11 11:48:47 parus volumio[1144]: errorCode: -65537 Oct 11 11:48:47 parus volumio[1144]: } Oct 11 11:48:47 parus volumio[1144]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 11 11:48:48 parus sudo[5614]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-11 11:47' Oct 11 11:48:48 parus sudo[5614]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"