-- Logs begin at Sat 2025-04-26 21:05:35 CEST, end at Sat 2025-04-26 21:12:50 CEST. -- Apr 26 21:11:55 udestue volumio[2844]: info: Updating volume from AirPlay: -1.88; 94% Apr 26 21:11:55 udestue volumio[2844]: info: VolumeController::SetAlsaVolume94 Apr 26 21:11:55 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:11:55 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:11:55 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:11:55 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Apr 26 21:11:55 udestue volumio[2844]: SPOTIFY: SPOTIFY VOLUME 100 Apr 26 21:11:55 udestue volumio[2844]: SPOTIFY: VOLUMIO VOLUME 94 Apr 26 21:11:55 udestue volumio[2844]: SPOTIFY: DELTA VOLUME ENOUGH: true Apr 26 21:11:55 udestue volumio[2844]: info: Setting Spotify Volume from Volumio: 94 Apr 26 21:11:56 udestue volumio[2844]: info: Updating volume from AirPlay: -3.75; 88% Apr 26 21:11:56 udestue volumio[2844]: info: VolumeController::SetAlsaVolume88 Apr 26 21:11:56 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:11:56 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:11:56 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:11:56 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 88 Apr 26 21:11:56 udestue volumio[2844]: SPOTIFY: SPOTIFY VOLUME 94 Apr 26 21:11:56 udestue volumio[2844]: SPOTIFY: VOLUMIO VOLUME 88 Apr 26 21:11:56 udestue volumio[2844]: SPOTIFY: DELTA VOLUME ENOUGH: true Apr 26 21:11:56 udestue volumio[2844]: info: Setting Spotify Volume from Volumio: 88 Apr 26 21:11:56 udestue volumio[2844]: info: Updating volume from AirPlay: -5.62; 81% Apr 26 21:11:56 udestue volumio[2844]: info: VolumeController::SetAlsaVolume81 Apr 26 21:11:56 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:11:56 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:11:56 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:11:56 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 81 Apr 26 21:11:56 udestue volumio[2844]: SPOTIFY: SPOTIFY VOLUME 88 Apr 26 21:11:56 udestue volumio[2844]: SPOTIFY: VOLUMIO VOLUME 81 Apr 26 21:11:56 udestue volumio[2844]: SPOTIFY: DELTA VOLUME ENOUGH: true Apr 26 21:11:56 udestue volumio[2844]: info: Setting Spotify Volume from Volumio: 81 Apr 26 21:11:57 udestue volumio[2844]: info: Updating volume from AirPlay: -7.5; 75% Apr 26 21:11:57 udestue volumio[2844]: info: VolumeController::SetAlsaVolume75 Apr 26 21:11:57 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:11:57 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:11:57 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:11:57 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:11:57 udestue volumio[2844]: SPOTIFY: SPOTIFY VOLUME 81 Apr 26 21:11:57 udestue volumio[2844]: SPOTIFY: VOLUMIO VOLUME 75 Apr 26 21:11:57 udestue volumio[2844]: SPOTIFY: DELTA VOLUME ENOUGH: true Apr 26 21:11:57 udestue volumio[2844]: info: Setting Spotify Volume from Volumio: 75 Apr 26 21:11:58 udestue volumio[2844]: SPOTIFY: SETTING SPOTIFY VOLUME 75 Apr 26 21:11:58 udestue volumio[2844]: info: Sending Spotify command with payload to local API: /player/volume Apr 26 21:12:01 udestue ntpd[1002]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:04 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:04 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:04 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:04 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:04 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:04 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:04 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:13 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:13 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:13 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:13 udestue shairport-sync[3070]: {"time":1745694604117,"response":"startAirplayPlayback Success"} % Total % Received % Xferd Average Speed Time Time Time Current Apr 26 21:12:13 udestue shairport-sync[3070]: Dload Upload Total Spent Left Speed Apr 26 21:12:13 udestue volumio[2844]: info: Apr 26 21:12:13 udestue volumio[2844]: ---------------------------- Client requests Stop Airplay Playback Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , stopAirplayPlayback Apr 26 21:12:13 udestue volumio[2844]: info: Airplay playback stop Apr 26 21:12:13 udestue volumio[2844]: info: Airplay Playback Stopped, clearing state Apr 26 21:12:13 udestue volumio[2844]: info: CoreStateMachine::resetVolumioState Apr 26 21:12:13 udestue volumio[2844]: info: CoreStateMachine::getcurrentVolume Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::volumioRetrievevolume Apr 26 21:12:13 udestue shairport-sync[3070]: [158B blob data] Apr 26 21:12:13 udestue volumio[2844]: info: VolumeController:: Volume=75 Mute =false Apr 26 21:12:13 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:13 udestue volumio[2844]: info: CoreStateMachine::updateTrackBlock Apr 26 21:12:13 udestue volumio[2844]: info: CorePlayQueue::getTrackBlock Apr 26 21:12:13 udestue volumio[2844]: info: CoreCommandRouter::volumioRetrievevolume Apr 26 21:12:13 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:14 udestue volumio[2844]: info: VolumeController:: Volume=75 Mute =false Apr 26 21:12:14 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:14 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:14 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="obtained new client token: AAADskVUmTXxwOvkTtnoRxS4OgS6QjJv2QOyrzOlkBTssTZGH6SUb9/cYYZNq0Ew9+LiTVSi+zhr2eqbRRorXB8rcvLsg0QByBYvMwjnIjxg/Yqnx6MGs2ns8OYQ4OykqrjoBUesTIF6GOQ9+9LDxi1zbenHO9cxhGWMKwMzYbQ1m/ohmWM7v1/Xh77xXnYPvi2W+YUnHSOlZsAXW6otE515Xf+mmOA/ad4P+5C13fzztRY8iDm2G5VO" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="completed keyexchange" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="completed challenge" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=info msg="authenticated AP as 1173493170" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=info msg="authenticated Login5 as 1173493170" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=info msg="accepted zeroconf user 1173493170 from MacBook Pro tilhørende Shanjeef" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="dealer connection opened" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=trace msg="starting accesspoint recv loop" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=trace msg="starting dealer recv loop" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=trace msg="received accesspoint ping" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=debug msg="received connection id: MWM3MGUyYzgtZTgzMS00MDcxLTkxYWQtMjllNDY2M2EwZjcxK2RlYWxlcit0Y3A6Ly8wYWNhNWEyOC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNEM4Q0FEQTM0MzlFQzg3RjU4NUU5NEI5RjcxOTc1RDM0MDJBODY2NEEyQTQyNDMwNEQ2RURBRTdEQUI5MjNGQg==" Apr 26 21:12:16 udestue go-librespot[3069]: time="2025-04-26T21:12:16+02:00" level=trace msg="received accesspoint pong ack" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="handling transfer player command from baf4c6a08ddeec810f997015f614fe59ed5193f7" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="resolved context of track" uri="spotify:user:1173493170:collection" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=trace msg="fetched new page 0 with 34 items (list: 34)" uri="spotify:user:1173493170:collection" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="loading track (paused: false, position: 151377ms)" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=trace msg="emitting websocket event: will_play" Apr 26 21:12:17 udestue volumio[2844]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","play_origin":"com.spotify.gaia"}} Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="selected format OGG_VORBIS_320 (f5fc635cf1d101835436136e6cd803f8071bd398)" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="requested aes key for file f5fc635cf1d101835436136e6cd803f8071bd398, gid: 4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3198" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="fetched first chunk of 14, total size is 7297906 bytes" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2043" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="fetched chunk 13/13, size: 482162" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="fetched chunk 12/13, size: 524288" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=trace msg="seek to 151377ms (diff: 156ms, samples: 6675725, bytes: 6528406)" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:17 udestue go-librespot[3069]: time="2025-04-26T21:12:17+02:00" level=debug msg="created new output device" Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=info msg="loaded track \"Vielleicht Vielleicht - Holy Priest & elMefti Remix\" (paused: false, position: 151377ms, duration: 169818ms, prefetched: false)" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=warning msg="cannot prefetch next track because the uri field is empty" Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=trace msg="emitting websocket event: metadata" Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=trace msg="emitting websocket event: active" Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=debug msg="sending successful reply for dealer request" Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","name":"Vielleicht Vielleicht - Holy Priest \u0026 elMefti Remix","artist_names":["MilleniumKid","JBS","Holy Priest","elMefti"],"album_name":"Vielleicht Vielleicht (Holy Priest \u0026 elMefti Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020913b71ef7c7435c6e481f18","position":151377,"duration":169818,"release_date":"year:2025 month:4 day:17","track_number":1,"disc_number":1}} Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: received: {"type":"active","data":null} Apr 26 21:12:18 udestue volumio[2844]: info: Aligning Spotify Volume to Volumio Volume Apr 26 21:12:18 udestue volumio[2844]: info: CoreCommandRouter::volumioGetState Apr 26 21:12:18 udestue volumio[2844]: info: Setting Spotify Volume from Volumio: 75 Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:18 udestue go-librespot[3069]: time="2025-04-26T21:12:18+02:00" level=trace msg="emitting websocket event: playing" Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","play_origin":"com.spotify.gaia"}} Apr 26 21:12:18 udestue volumio[2844]: info: Spotify is playing in volatile mode Apr 26 21:12:18 udestue volumio[2844]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: UNSET VOLATILE Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: {"status":"play","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"airplay","codec":"","seek":0,"duration":0,"samplerate":"","bitdepth":"","channels":2,"consume":false,"volume":75,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"disableUiControls":true,"service":"airplay_emulation"} Apr 26 21:12:18 udestue volumio[2844]: info: Setting Spotify stop after unset volatile call Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: PUSH STATE SPOTIFY Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: {"status":"play","service":"spop","title":"Vielleicht Vielleicht - Holy Priest & elMefti Remix","artist":"MilleniumKid, JBS, Holy Priest, elMefti","album":"Vielleicht Vielleicht (Holy Priest & elMefti Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e020913b71ef7c7435c6e481f18","uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","trackType":"spotify","seek":151377,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 26 21:12:18 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:18 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:18 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:18 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: PUSH STATE SPOTIFY Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: {"status":"play","service":"spop","title":"Vielleicht Vielleicht - Holy Priest & elMefti Remix","artist":"MilleniumKid, JBS, Holy Priest, elMefti","album":"Vielleicht Vielleicht (Holy Priest & elMefti Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e020913b71ef7c7435c6e481f18","uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","trackType":"spotify","seek":151377,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 26 21:12:18 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:18 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:18 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:18 udestue volumio[2844]: info: Spotify Stop Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: SPOTIFY STOP Apr 26 21:12:18 udestue volumio[2844]: SPOTIFY: {"status":"play","title":"Vielleicht Vielleicht - Holy Priest & elMefti Remix","artist":"MilleniumKid, JBS, Holy Priest, elMefti","album":"Vielleicht Vielleicht (Holy Priest & elMefti Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e020913b71ef7c7435c6e481f18","uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","trackType":"spotify","codec":"ogg","seek":151377,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":75,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Apr 26 21:12:19 udestue volumio[2844]: SPOTIFY: SETTING SPOTIFY VOLUME 75 Apr 26 21:12:19 udestue volumio[2844]: info: Sending Spotify command with payload to local API: /player/volume Apr 26 21:12:19 udestue go-librespot[3069]: time="2025-04-26T21:12:19+02:00" level=debug msg="update volume to 49151/65535" Apr 26 21:12:20 udestue go-librespot[3069]: time="2025-04-26T21:12:20+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 26 21:12:20 udestue go-librespot[3069]: time="2025-04-26T21:12:20+02:00" level=trace msg="emitting websocket event: volume" Apr 26 21:12:20 udestue volumio[2844]: SPOTIFY: received: {"type":"volume","data":{"value":75,"max":100}} Apr 26 21:12:20 udestue volumio[2844]: SPOTIFY: RECEIVED SPOTIFY VOLUME 75 Apr 26 21:12:23 udestue go-librespot[3069]: time="2025-04-26T21:12:23+02:00" level=debug msg="handling skip_prev player command from baf4c6a08ddeec810f997015f614fe59ed5193f7" Apr 26 21:12:23 udestue go-librespot[3069]: time="2025-04-26T21:12:23+02:00" level=debug msg="seek track to 0ms" Apr 26 21:12:23 udestue go-librespot[3069]: time="2025-04-26T21:12:23+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:23 udestue go-librespot[3069]: time="2025-04-26T21:12:23+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:23 udestue go-librespot[3069]: time="2025-04-26T21:12:23+02:00" level=trace msg="scheduling prefetch in 140s" Apr 26 21:12:23 udestue go-librespot[3069]: time="2025-04-26T21:12:23+02:00" level=trace msg="emitting websocket event: seek" Apr 26 21:12:23 udestue go-librespot[3069]: time="2025-04-26T21:12:23+02:00" level=debug msg="sending successful reply for dealer request" Apr 26 21:12:23 udestue volumio[2844]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","position":0,"duration":169818,"play_origin":"com.spotify.gaia"}} Apr 26 21:12:23 udestue volumio[2844]: SPOTIFY: PUSH STATE SPOTIFY Apr 26 21:12:23 udestue volumio[2844]: SPOTIFY: {"status":"play","service":"spop","title":"Vielleicht Vielleicht - Holy Priest & elMefti Remix","artist":"MilleniumKid, JBS, Holy Priest, elMefti","album":"Vielleicht Vielleicht (Holy Priest & elMefti Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e020913b71ef7c7435c6e481f18","uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","trackType":"spotify","seek":0,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 26 21:12:23 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:23 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:23 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:23 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:23 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=debug msg="handling seek_to player command from baf4c6a08ddeec810f997015f614fe59ed5193f7" Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=debug msg="seek track to 20688ms" Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=trace msg="seek to 20688ms (diff: 172ms, samples: 912340, bytes: 867163)" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=trace msg="scheduling prefetch in 119s" Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=trace msg="emitting websocket event: seek" Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=debug msg="sending successful reply for dealer request" Apr 26 21:12:25 udestue volumio[2844]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","position":20688,"duration":169818,"play_origin":"com.spotify.gaia"}} Apr 26 21:12:25 udestue volumio[2844]: SPOTIFY: PUSH STATE SPOTIFY Apr 26 21:12:25 udestue volumio[2844]: SPOTIFY: {"status":"play","service":"spop","title":"Vielleicht Vielleicht - Holy Priest & elMefti Remix","artist":"MilleniumKid, JBS, Holy Priest, elMefti","album":"Vielleicht Vielleicht (Holy Priest & elMefti Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e020913b71ef7c7435c6e481f18","uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","trackType":"spotify","seek":20688,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 26 21:12:25 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:25 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:25 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:25 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:25 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=debug msg="handling seek_to player command from baf4c6a08ddeec810f997015f614fe59ed5193f7" Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=debug msg="seek track to 52490ms" Apr 26 21:12:25 udestue go-librespot[3069]: time="2025-04-26T21:12:25+02:00" level=trace msg="seek to 52490ms (diff: 154ms, samples: 2314809, bytes: 2186355)" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:26 udestue go-librespot[3069]: time="2025-04-26T21:12:26+02:00" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:26 udestue go-librespot[3069]: time="2025-04-26T21:12:26+02:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:26 udestue go-librespot[3069]: time="2025-04-26T21:12:26+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:26 udestue go-librespot[3069]: time="2025-04-26T21:12:26+02:00" level=trace msg="scheduling prefetch in 88s" Apr 26 21:12:26 udestue go-librespot[3069]: time="2025-04-26T21:12:26+02:00" level=trace msg="emitting websocket event: seek" Apr 26 21:12:26 udestue go-librespot[3069]: time="2025-04-26T21:12:26+02:00" level=debug msg="sending successful reply for dealer request" Apr 26 21:12:26 udestue volumio[2844]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","position":52490,"duration":169818,"play_origin":"com.spotify.gaia"}} Apr 26 21:12:26 udestue volumio[2844]: SPOTIFY: PUSH STATE SPOTIFY Apr 26 21:12:26 udestue volumio[2844]: SPOTIFY: {"status":"play","service":"spop","title":"Vielleicht Vielleicht - Holy Priest & elMefti Remix","artist":"MilleniumKid, JBS, Holy Priest, elMefti","album":"Vielleicht Vielleicht (Holy Priest & elMefti Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e020913b71ef7c7435c6e481f18","uri":"spotify:track:4pRAG3h4ZTfyEhRMytddzd","trackType":"spotify","seek":52490,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 26 21:12:26 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:26 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:26 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:26 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:26 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:26 udestue go-librespot[3069]: time="2025-04-26T21:12:26+02:00" level=debug msg="fetched chunk 7/13, size: 524288" uri="spotify:track:4pRAG3h4ZTfyEhRMytddzd" Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=debug msg="handling play player command from baf4c6a08ddeec810f997015f614fe59ed5193f7" Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:3h08ycWCujPPoryF0Lh6wp" Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=trace msg="fetched new page 0 with 48 items (list: 48)" uri="spotify:playlist:3h08ycWCujPPoryF0Lh6wp" Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:0hKtu53OlIFXVuYkZwcn3o" Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=trace msg="emitting websocket event: will_play" Apr 26 21:12:28 udestue volumio[2844]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0hKtu53OlIFXVuYkZwcn3o","play_origin":"playlist"}} Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=debug msg="selected format OGG_VORBIS_320 (9a1335ec5bd6fbfee5f81708567ee7b0dac582eb)" uri="spotify:track:0hKtu53OlIFXVuYkZwcn3o" Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=debug msg="requested aes key for file 9a1335ec5bd6fbfee5f81708567ee7b0dac582eb, gid: 0hKtu53OlIFXVuYkZwcn3o" Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=debug msg="fetched first chunk of 14, total size is 7109593 bytes" uri="spotify:track:0hKtu53OlIFXVuYkZwcn3o" Apr 26 21:12:28 udestue go-librespot[3069]: time="2025-04-26T21:12:28+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:0hKtu53OlIFXVuYkZwcn3o" Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=info msg="loaded track \"Cinderella\" (paused: false, position: 1ms, duration: 169840ms, prefetched: false)" uri="spotify:track:0hKtu53OlIFXVuYkZwcn3o" Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:0hKtu53OlIFXVuYkZwcn3o" Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:0hKtu53OlIFXVuYkZwcn3o" Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=trace msg="scheduling prefetch in 140s" Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=trace msg="emitting websocket event: metadata" Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=debug msg="sending successful reply for dealer request" Apr 26 21:12:29 udestue volumio[2844]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0hKtu53OlIFXVuYkZwcn3o","name":"Cinderella","artist_names":["Future","Metro Boomin","Travis Scott"],"album_name":"WE DON'T TRUST YOU","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a46b07c291e6dfdee13b3ee8","position":1,"duration":169840,"release_date":"year:2024 month:3 day:22","track_number":9,"disc_number":1}} Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:0hKtu53OlIFXVuYkZwcn3o" Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:29 udestue go-librespot[3069]: time="2025-04-26T21:12:29+02:00" level=trace msg="emitting websocket event: playing" Apr 26 21:12:29 udestue volumio[2844]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0hKtu53OlIFXVuYkZwcn3o","play_origin":"playlist"}} Apr 26 21:12:29 udestue volumio[2844]: SPOTIFY: PUSH STATE SPOTIFY Apr 26 21:12:29 udestue volumio[2844]: SPOTIFY: {"status":"play","service":"spop","title":"Cinderella","artist":"Future, Metro Boomin, Travis Scott","album":"WE DON'T TRUST YOU","albumart":"https://i.scdn.co/image/ab67616d00001e02a46b07c291e6dfdee13b3ee8","uri":"spotify:track:0hKtu53OlIFXVuYkZwcn3o","trackType":"spotify","seek":1,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 26 21:12:29 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:29 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:29 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:29 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:29 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:29 udestue volumio[2844]: SPOTIFY: PUSH STATE SPOTIFY Apr 26 21:12:29 udestue volumio[2844]: SPOTIFY: {"status":"play","service":"spop","title":"Cinderella","artist":"Future, Metro Boomin, Travis Scott","album":"WE DON'T TRUST YOU","albumart":"https://i.scdn.co/image/ab67616d00001e02a46b07c291e6dfdee13b3ee8","uri":"spotify:track:0hKtu53OlIFXVuYkZwcn3o","trackType":"spotify","seek":1001,"duration":169,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 26 21:12:29 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:29 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:29 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:29 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:29 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:30 udestue go-librespot[3069]: time="2025-04-26T21:12:30+02:00" level=debug msg="handling play player command from baf4c6a08ddeec810f997015f614fe59ed5193f7" Apr 26 21:12:30 udestue go-librespot[3069]: time="2025-04-26T21:12:30+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:3h08ycWCujPPoryF0Lh6wp" Apr 26 21:12:30 udestue go-librespot[3069]: time="2025-04-26T21:12:30+02:00" level=trace msg="fetched new page 0 with 48 items (list: 48)" uri="spotify:playlist:3h08ycWCujPPoryF0Lh6wp" Apr 26 21:12:30 udestue go-librespot[3069]: time="2025-04-26T21:12:30+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:43KrLcrVbDBimYtjKswIL3" Apr 26 21:12:30 udestue go-librespot[3069]: time="2025-04-26T21:12:30+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:30 udestue go-librespot[3069]: time="2025-04-26T21:12:30+02:00" level=trace msg="emitting websocket event: will_play" Apr 26 21:12:30 udestue volumio[2844]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:43KrLcrVbDBimYtjKswIL3","play_origin":"playlist"}} Apr 26 21:12:30 udestue go-librespot[3069]: time="2025-04-26T21:12:30+02:00" level=debug msg="selected format OGG_VORBIS_320 (378848c19b2e8916d7a0dba798420f886299d52e)" uri="spotify:track:43KrLcrVbDBimYtjKswIL3" Apr 26 21:12:30 udestue go-librespot[3069]: time="2025-04-26T21:12:30+02:00" level=debug msg="requested aes key for file 378848c19b2e8916d7a0dba798420f886299d52e, gid: 43KrLcrVbDBimYtjKswIL3" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=debug msg="fetched first chunk of 15, total size is 7762164 bytes" uri="spotify:track:43KrLcrVbDBimYtjKswIL3" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=info msg="loaded track \"SIMPLE\" (paused: false, position: 0ms, duration: 154800ms, prefetched: false)" uri="spotify:track:43KrLcrVbDBimYtjKswIL3" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:43KrLcrVbDBimYtjKswIL3" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:43KrLcrVbDBimYtjKswIL3" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=trace msg="scheduling prefetch in 125s" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=trace msg="emitting websocket event: metadata" Apr 26 21:12:31 udestue volumio[2844]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:43KrLcrVbDBimYtjKswIL3","name":"SIMPLE","artist_names":["$NOT"],"album_name":"SIMPLE","album_cover_url":"https://i.scdn.co/image/ab67616d00001e022b8cd61360e6fb9610214e9e","position":0,"duration":154800,"release_date":"year:2022 month:10 day:14","track_number":1,"disc_number":1}} Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=debug msg="sending successful reply for dealer request" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:43KrLcrVbDBimYtjKswIL3" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 26 21:12:31 udestue go-librespot[3069]: time="2025-04-26T21:12:31+02:00" level=trace msg="emitting websocket event: playing" Apr 26 21:12:31 udestue volumio[2844]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:43KrLcrVbDBimYtjKswIL3","play_origin":"playlist"}} Apr 26 21:12:31 udestue volumio[2844]: SPOTIFY: PUSH STATE SPOTIFY Apr 26 21:12:31 udestue volumio[2844]: SPOTIFY: {"status":"play","service":"spop","title":"SIMPLE","artist":"$NOT","album":"SIMPLE","albumart":"https://i.scdn.co/image/ab67616d00001e022b8cd61360e6fb9610214e9e","uri":"spotify:track:43KrLcrVbDBimYtjKswIL3","trackType":"spotify","seek":1000,"duration":154,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 26 21:12:31 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:31 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:31 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 26 21:12:31 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:31 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:31 udestue volumio[2844]: SPOTIFY: PUSH STATE SPOTIFY Apr 26 21:12:31 udestue volumio[2844]: SPOTIFY: {"status":"play","service":"spop","title":"SIMPLE","artist":"$NOT","album":"SIMPLE","albumart":"https://i.scdn.co/image/ab67616d00001e022b8cd61360e6fb9610214e9e","uri":"spotify:track:43KrLcrVbDBimYtjKswIL3","trackType":"spotify","seek":1000,"duration":154,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 26 21:12:31 udestue volumio[2844]: info: CoreCommandRouter::servicePushState Apr 26 21:12:31 udestue volumio[2844]: info: CoreStateMachine::pushState Apr 26 21:12:31 udestue volumio[2844]: info: CoreCommandRouter::volumioPushState Apr 26 21:12:31 udestue volumio[2844]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Apr 26 21:12:35 udestue volumio[2844]: verbose: New Socket.io Connection to 192.168.0.22 from 192.168.0.97 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 6 Apr 26 21:12:35 udestue volumio[2844]: info: Received Get System Info Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 26 21:12:35 udestue volumio[2844]: info: Discovery: Getting this device information Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::volumioGetState Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::volumioGetState Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::volumioGetVisibleSources Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::volumioGetState Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 26 21:12:35 udestue volumio[2844]: info: Received Get System Info Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 26 21:12:35 udestue volumio[2844]: info: Discovery: Getting this device information Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::volumioGetState Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::volumioGetState Apr 26 21:12:35 udestue volumio[2844]: info: Listing playlists Apr 26 21:12:35 udestue volumio[2844]: info: CoreCommandRouter::volumioGetQueue Apr 26 21:12:35 udestue volumio[2844]: info: CoreStateMachine::getQueue Apr 26 21:12:35 udestue volumio[2844]: info: CorePlayQueue::getQueue Apr 26 21:12:36 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 26 21:12:41 udestue go-librespot[3069]: time="2025-04-26T21:12:41+02:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:43KrLcrVbDBimYtjKswIL3" Apr 26 21:12:45 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 26 21:12:45 udestue volumio[2844]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 26 21:12:46 udestue go-librespot[3069]: time="2025-04-26T21:12:46+02:00" level=trace msg="sent dealer ping" Apr 26 21:12:46 udestue go-librespot[3069]: time="2025-04-26T21:12:46+02:00" level=trace msg="received dealer pong" Apr 26 21:12:50 udestue volumio[2844]: info: Starting Uninstall of plugin user_interface - touch_display Apr 26 21:12:50 udestue volumio[2844]: info: Uninstalling plugin touch_display Apr 26 21:12:50 udestue sudo[3566]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Apr 26 21:12:50 udestue sudo[3566]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 26 21:12:50 udestue sudo[3566]: pam_unix(sudo:session): session closed for user root Apr 26 21:12:50 udestue sudo[3569]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start getty@tty1.service Apr 26 21:12:50 udestue sudo[3569]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 26 21:12:50 udestue sudo[3572]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl enable getty@tty1.service Apr 26 21:12:50 udestue sudo[3572]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 26 21:12:50 udestue volumio[2844]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Apr 26 21:12:50 udestue volumio[2844]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 26 21:12:50 udestue volumio[2844]: TypeError: Cannot read property 'split' of undefined Apr 26 21:12:50 udestue volumio[2844]: at /data/plugins/user_interface/touch_display/index.js:1258:37 Apr 26 21:12:50 udestue volumio[2844]: at ChildProcess.exithandler (child_process.js:299:7) Apr 26 21:12:50 udestue volumio[2844]: at ChildProcess.emit (events.js:315:20) Apr 26 21:12:50 udestue volumio[2844]: at maybeClose (internal/child_process.js:1048:16) Apr 26 21:12:50 udestue volumio[2844]: at Socket. (internal/child_process.js:439:11) Apr 26 21:12:50 udestue volumio[2844]: at Socket.emit (events.js:315:20) Apr 26 21:12:50 udestue volumio[2844]: at Pipe. (net.js:673:12) Apr 26 21:12:50 udestue volumio[2844]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 26 21:12:50 udestue sudo[3575]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumio-kiosk.service Apr 26 21:12:50 udestue sudo[3575]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 26 21:12:50 udestue systemd[1]: Created slice system-getty.slice. Apr 26 21:12:50 udestue systemd[1]: Started Getty on tty1. Apr 26 21:12:50 udestue sudo[3569]: pam_unix(sudo:session): session closed for user root Apr 26 21:12:50 udestue systemd[1]: Reloading. Apr 26 21:12:50 udestue sudo[3575]: pam_unix(sudo:session): session closed for user root Apr 26 21:12:50 udestue systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Apr 26 21:12:50 udestue sudo[3602]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-26 21:11 Apr 26 21:12:50 udestue sudo[3602]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"