Oct 15 18:48:07 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:07.774+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s Oct 15 18:48:07 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:07.852+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=http://pushupdates.volumio.org duration=74.471386ms Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.037+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=263.534441ms Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.070+02:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=http://cddb.volumio.org duration=295.030307ms error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.258+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=http://plugins.volumio.org duration=479.536469ms Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.279+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://securetoken.googleapis.com duration=499.437939ms Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.290+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=515.701415ms Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.302+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://www.googleapis.com duration=523.540629ms Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.316+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=536.628867ms Oct 15 18:48:08 volumio volumio[1249]: verbose: New Socket.io Connection to 192.168.178.20 from 192.168.178.184 UA: Mozilla/5.0 (Linux; Android 11; M2101K9G Build/RKQ1.201112.002; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/154.0.8037.106 Mobile Safari/537.36 VolumioApp/6.260930.0 Engine version: 3 Transport: polling Total Clients: 6 Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.370+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://functions.volumio.cloud duration=593.305331ms Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.373+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://functions.volumio.cloud duration=596.545152ms Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.382+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://database.volumio.cloud duration=603.978067ms Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.383+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=602.433233ms Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::volumioGetVisibleSources Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::volumioGetState Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 15 18:48:08 volumio volumio[1249]: info: Received Get System Info Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 15 18:48:08 volumio volumio[1249]: info: Discovery: Getting this device information Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::volumioGetState Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::volumioGetState Oct 15 18:48:08 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:08.568+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=468.91081ms timeout=10s endpoint=https://google.com duration=790.249007ms Oct 15 18:48:08 volumio volumio[1249]: info: Listing playlists Oct 15 18:48:08 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 15 18:48:12 volumio volumio[1249]: info: CoreCommandRouter::volumioNext Oct 15 18:48:12 volumio volumio[1249]: info: CoreStateMachine::next Oct 15 18:48:12 volumio volumio[1249]: info: Spotify next Oct 15 18:48:12 volumio volumio[1249]: info: Sending Spotify command to local API: /player/next Oct 15 18:48:12 volumio go-librespot[1552]: time="2026-10-15T18:48:12+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:12 volumio go-librespot[1552]: time="2026-10-15T18:48:12+02:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:0I4yYE831a8SW8QIx6bz4x" Oct 15 18:48:12 volumio go-librespot[1552]: time="2026-10-15T18:48:12+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 15 18:48:12 volumio go-librespot[1552]: time="2026-10-15T18:48:12+02:00" level=trace msg="emitting websocket event: will_play" Oct 15 18:48:12 volumio volumio[1249]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1DWSDoVybeQisg","uri":"spotify:track:7B9F9nLxe7MZgZ68Jj86Fn","play_origin":"playlist"}} Oct 15 18:48:12 volumio go-librespot[1552]: time="2026-10-15T18:48:12+02:00" level=debug msg="selected format OGG_VORBIS_320 (92a323623e4e122172e19ffe0b2eb591c126b5d1)" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:12 volumio go-librespot[1552]: time="2026-10-15T18:48:12+02:00" level=debug msg="requested aes key for file 92a323623e4e122172e19ffe0b2eb591c126b5d1, gid: 7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:12 volumio go-librespot[1552]: time="2026-10-15T18:48:12+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=debug msg="fetched first chunk of 14, total size is 7299984 bytes" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=debug msg="track has no narration" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=info msg="loaded track \"I Can See For Miles - Mono Version\" (paused: false, position: 0ms, duration: 247306ms, prefetched: false)" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=trace msg="scheduling prefetch in 217s" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=trace msg="emitting websocket event: metadata" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=trace msg="emitting websocket event: playing" Oct 15 18:48:13 volumio volumio[1249]: SPOTIFY: received: {"type":"metadata","data":{"album_cover_url":"https://i.scdn.co/image/ab67616d00001e0234894946601823e27fc08538","album_name":"The Who Sell Out (Super Deluxe)","artist_names":["The Who"],"bit_depth":null,"bitrate":320,"codec":"vorbis","disc_number":1,"duration":247306,"format":"OGG_VORBIS_320","name":"I Can See For Miles - Mono Version","position":0,"release_date":"year:2021 month:4 day:23","sample_rate":44100,"track_number":7,"uri":"spotify:track:7B9F9nLxe7MZgZ68Jj86Fn"}} Oct 15 18:48:13 volumio volumio[1249]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1DWSDoVybeQisg","uri":"spotify:track:7B9F9nLxe7MZgZ68Jj86Fn","resume":false,"play_origin":"playlist"}} Oct 15 18:48:13 volumio volumio[1249]: SPOTIFY: PUSH STATE SPOTIFY Oct 15 18:48:13 volumio volumio[1249]: SPOTIFY: {"status":"play","service":"spop","title":"I Can See For Miles - Mono Version","artist":"The Who","album":"The Who Sell Out (Super Deluxe)","albumart":"https://i.scdn.co/image/ab67616d00001e0234894946601823e27fc08538","uri":"spotify:track:7B9F9nLxe7MZgZ68Jj86Fn","trackType":"spotify","seek":0,"duration":247,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 15 18:48:13 volumio volumio[1249]: info: CoreCommandRouter::servicePushState Oct 15 18:48:13 volumio volumio[1249]: info: CoreStateMachine::pushState Oct 15 18:48:13 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 18:48:13 volumio volumio[1249]: info: CoreCommandRouter::volumioPushState Oct 15 18:48:13 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:13.245+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" state=STATUS_PLAYING positionMs=0 volume=50 Oct 15 18:48:13 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:13.247+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01 @ 0x318e450" state=STATUS_PLAYING positionMs=0 volume=50 Oct 15 18:48:13 volumio volumio[1249]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:13 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:13.385+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" id=spotify:track:7B9F9nLxe7MZgZ68Jj86Fn title="I Can See For Miles - Mono Version" Oct 15 18:48:13 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:13.385+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01 @ 0x318e450" id=spotify:track:7B9F9nLxe7MZgZ68Jj86Fn title="I Can See For Miles - Mono Version" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 15 18:48:13 volumio go-librespot[1552]: time="2026-10-15T18:48:13+02:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:13 volumio volumio[1249]: SPOTIFY: PUSH STATE SPOTIFY Oct 15 18:48:13 volumio volumio[1249]: SPOTIFY: {"status":"play","service":"spop","title":"I Can See For Miles - Mono Version","artist":"The Who","album":"The Who Sell Out (Super Deluxe)","albumart":"https://i.scdn.co/image/ab67616d00001e0234894946601823e27fc08538","uri":"spotify:track:7B9F9nLxe7MZgZ68Jj86Fn","trackType":"spotify","seek":0,"duration":247,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 15 18:48:13 volumio volumio[1249]: info: CoreCommandRouter::servicePushState Oct 15 18:48:13 volumio volumio[1249]: info: CoreStateMachine::pushState Oct 15 18:48:13 volumio volumio[1249]: info: CoreCommandRouter::volumioPushState Oct 15 18:48:13 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:13.537+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" state=STATUS_PLAYING positionMs=0 volume=50 Oct 15 18:48:13 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:13.537+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01 @ 0x318e450" state=STATUS_PLAYING positionMs=0 volume=50 Oct 15 18:48:13 volumio volumio[1249]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Oct 15 18:48:13 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:13.684+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" id=spotify:track:7B9F9nLxe7MZgZ68Jj86Fn title="I Can See For Miles - Mono Version" Oct 15 18:48:13 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:13.685+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01 @ 0x318e450" id=spotify:track:7B9F9nLxe7MZgZ68Jj86Fn title="I Can See For Miles - Mono Version" Oct 15 18:48:29 volumio go-librespot[1552]: time="2026-10-15T18:48:29+02:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:48:31 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:31.897+02:00 level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=473.591639ms timeout=3s volume=49 Oct 15 18:48:31 volumio volumio[1249]: info: VolumeController::SetAlsaVolume49 Oct 15 18:48:31 volumio volumio[1249]: info: CoreStateMachine::pushState Oct 15 18:48:31 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 18:48:31 volumio volumio[1249]: info: CoreCommandRouter::volumioPushState Oct 15 18:48:31 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:31.928+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" state=STATUS_PLAYING positionMs=18000 volume=49 Oct 15 18:48:31 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:31.929+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01 @ 0x318e450" state=STATUS_PLAYING positionMs=18000 volume=49 Oct 15 18:48:31 volumio volumio[1249]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Oct 15 18:48:31 volumio volumio[1249]: SPOTIFY: SPOTIFY VOLUME 50 Oct 15 18:48:31 volumio volumio[1249]: SPOTIFY: VOLUMIO VOLUME 49 Oct 15 18:48:31 volumio volumio[1249]: SPOTIFY: DELTA VOLUME ENOUGH: false Oct 15 18:48:32 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:32.104+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" id=spotify:track:7B9F9nLxe7MZgZ68Jj86Fn title="I Can See For Miles - Mono Version" Oct 15 18:48:32 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:32.105+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01 @ 0x318e450" id=spotify:track:7B9F9nLxe7MZgZ68Jj86Fn title="I Can See For Miles - Mono Version" Oct 15 18:48:33 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:33.396+02:00 level=INFO msg="set volume" component=server type=REQUEST_TYPE_SET_VOLUME peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" latency=503.289121ms timeout=3s volume=48 Oct 15 18:48:33 volumio volumio[1249]: info: VolumeController::SetAlsaVolume48 Oct 15 18:48:33 volumio volumio[1249]: info: CoreStateMachine::pushState Oct 15 18:48:33 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 15 18:48:33 volumio volumio[1249]: info: CoreCommandRouter::volumioPushState Oct 15 18:48:33 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:33.426+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" state=STATUS_PLAYING positionMs=20000 volume=48 Oct 15 18:48:33 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:33.426+02:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01 @ 0x318e450" state=STATUS_PLAYING positionMs=20000 volume=48 Oct 15 18:48:33 volumio volumio[1249]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Oct 15 18:48:33 volumio volumio[1249]: SPOTIFY: SPOTIFY VOLUME 50 Oct 15 18:48:33 volumio volumio[1249]: SPOTIFY: VOLUMIO VOLUME 48 Oct 15 18:48:33 volumio volumio[1249]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 15 18:48:33 volumio volumio[1249]: info: Setting Spotify Volume from Volumio: 48 Oct 15 18:48:33 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:33.784+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.178.184:46774,00:00:00:00:00:00%01 @ 0x3592840" id=spotify:track:7B9F9nLxe7MZgZ68Jj86Fn title="I Can See For Miles - Mono Version" Oct 15 18:48:33 volumio volumio5-onboarding[1707]: time=2026-10-15T18:48:33.785+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01 @ 0x318e450" id=spotify:track:7B9F9nLxe7MZgZ68Jj86Fn title="I Can See For Miles - Mono Version" Oct 15 18:48:34 volumio volumio[1249]: SPOTIFY: SETTING SPOTIFY VOLUME 48 Oct 15 18:48:34 volumio volumio[1249]: info: Sending Spotify command with payload to local API: /player/volume Oct 15 18:48:34 volumio go-librespot[1552]: time="2026-10-15T18:48:34+02:00" level=debug msg="update volume requested to 31456/65535" Oct 15 18:48:35 volumio go-librespot[1552]: time="2026-10-15T18:48:35+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 15 18:48:35 volumio go-librespot[1552]: time="2026-10-15T18:48:35+02:00" level=trace msg="emitting websocket event: volume" Oct 15 18:48:35 volumio volumio[1249]: SPOTIFY: received: {"type":"volume","data":{"max":100,"value":48}} Oct 15 18:48:35 volumio volumio[1249]: SPOTIFY: RECEIVED SPOTIFY VOLUME 48 Oct 15 18:48:41 volumio volumio[1249]: info: CoreCommandRouter::volumioGetQueue Oct 15 18:48:41 volumio volumio[1249]: info: CoreStateMachine::getQueue Oct 15 18:48:41 volumio volumio[1249]: info: CorePlayQueue::getQueue Oct 15 18:48:47 volumio go-librespot[1552]: time="2026-10-15T18:48:47+02:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:49:01 volumio volumio[1249]: Searching plugin music_service/spop Oct 15 18:49:01 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: spop , search Oct 15 18:49:02 volumio volumio[1249]: info: All search sources collected, pushing search results Oct 15 18:49:05 volumio go-librespot[1552]: time="2026-10-15T18:49:05+02:00" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:49:07 volumio volumio[1249]: Searching plugin music_service/spop Oct 15 18:49:07 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: spop , search Oct 15 18:49:08 volumio volumio[1249]: Searching plugin music_service/spop Oct 15 18:49:08 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: spop , search Oct 15 18:49:08 volumio volumio[1249]: info: All search sources collected, pushing search results Oct 15 18:49:09 volumio volumio[1249]: info: All search sources collected, pushing search results Oct 15 18:49:09 volumio volumio[1249]: Searching plugin music_service/spop Oct 15 18:49:09 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: spop , search Oct 15 18:49:10 volumio volumio[1249]: info: All search sources collected, pushing search results Oct 15 18:49:15 volumio volumio[1249]: Searching plugin music_service/spop Oct 15 18:49:15 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: spop , search Oct 15 18:49:16 volumio volumio[1249]: info: All search sources collected, pushing search results Oct 15 18:49:23 volumio go-librespot[1552]: time="2026-10-15T18:49:23+02:00" level=debug msg="fetched chunk 7/13, size: 524288" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:49:40 volumio go-librespot[1552]: time="2026-10-15T18:49:40+02:00" level=debug msg="fetched chunk 8/13, size: 524288" uri="spotify:track:7B9F9nLxe7MZgZ68Jj86Fn" Oct 15 18:49:43 volumio volumio[1249]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Oct 15 18:49:43 volumio volumio[1249]: info: In handleBrowseUri, curUri=spotify:artist:79lPJRYKR16XUoD1dQ3MJu Oct 15 18:49:44 volumio volumio[1249]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 15 18:49:44 volumio volumio[1249]: TypeError: Cannot read properties of undefined (reading 'url') Oct 15 18:49:44 volumio volumio[1249]: at /data/plugins/music_service/spop/index.js:3360:60 Oct 15 18:49:44 volumio volumio[1249]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Oct 15 18:49:44 volumio volumio[1249]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 15 18:49:45 volumio sudo[5155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-15 18:48' Oct 15 18:49:45 volumio sudo[5155]: 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"