-- Logs begin at Fri 2024-09-06 11:08:06 EDT, end at Fri 2024-09-06 15:35:49 EDT. -- Sep 06 15:34:04 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPlay Sep 06 15:34:04 volumioecs volumio[1024]: info: CoreStateMachine::play index undefined Sep 06 15:34:04 volumioecs volumio[1024]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 06 15:34:04 volumioecs volumio[1024]: info: CorePlayQueue::getTrack 0 Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="obtained new client token: AAAELAsPOxjwgzm4SpaAuNgoh7ZGn/Cpppjq5cJ7C8rNvCjNYPibUQ56eZFVaCUw7BaDcO20HJ3DzHhhfrIUdgmpc0kYiZJC2E2vved4j6Y57Zu62K1Vr6Z6F0ZbbOyyKMC6bXLb3v2VTDxE5FNbZV1QGuJmAgd4jQVTnr51tuAFh7+e4in8cqa9Xf+HO1hEqj7Jdyic/+Pn+xpE80N/2+VLEiHexG/1yGxtt2b923fWByI+II91ZfDs" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="completed keyexchange" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="completed challenge" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="authenticated as bridgecrud" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="authenticated as bridgecrud" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="dealer connection opened" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=info msg="accepted zeroconf user bridgecrud from Pixel 7" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="autoplay enabled: false" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="received connection id: NTJjNDFiZjQtZGQxMS00YTNiLWFkY2EtMjgwZDI2ZmIzNmZhK2RlYWxlcit0Y3A6Ly8wYWNiZjkxMi5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArNENERjlCQTc0MTVGNTRDNEM1QjQxQTIxOUJDQUExMEM1MTk4NTgyRDk1MzRCOTk3RDQ0QjJBRDAxQkZDNjA4Ng==" Sep 06 15:34:12 volumioecs go-librespot[1576]: time="2024-09-06T15:34:12-04:00" level=debug msg="put connect state because NEW_DEVICE" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="handling transfer player command from 177d4c2c7b4693890c166b11383a94abd2a15c78" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="resolved context of track" uri="spotify:playlist:3xvlxS0LVHGyfMUiyuoK4D" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=trace msg="fetched new page 0 with 20 items (list: 20)" uri="spotify:playlist:3xvlxS0LVHGyfMUiyuoK4D" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="loading track (paused: true, position: 85530ms)" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=trace msg="emitting websocket event: will_play" Sep 06 15:34:13 volumioecs volumio[1024]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2eItD5YrDMy2vxgBgxpaDy","play_origin":"playlist"}} Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1138" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="selected format OGG_VORBIS_320 (f89c610e5954c8e0f1a6eeeb64f8b42c88b536f9)" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="requested aes key for file f89c610e5954c8e0f1a6eeeb64f8b42c88b536f9, gid: 2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="fetched first chunk of 12, total size is 6280144 bytes" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="fetched chunk 8/11, size: 524288" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="fetched chunk 7/11, size: 524288" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="fetched chunk 9/11, size: 524288" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="fetched chunk 6/11, size: 524288" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=trace msg="seek to 85530ms (diff: 39ms, samples: 3771873, bytes: 3265859)" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 16666 us, period size = 735 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 30 frames" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="created new output device" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=info msg="loaded track \"Monastery Worms\" (paused: true, position: 85530ms, duration: 164806ms, prefetched: false)" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=trace msg="emitting websocket event: metadata" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=trace msg="emitting websocket event: active" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="sending successful reply for dealer request" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 06 15:34:13 volumioecs volumio[1024]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2eItD5YrDMy2vxgBgxpaDy","name":"Monastery Worms","artist_names":["Cryptivore"],"album_name":"Celestial Extinction","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b63a333ebf8c545e933fa5f7","position":85530,"duration":164806,"release_date":"year:2022 month:3 day:24","track_number":6,"disc_number":1}} Sep 06 15:34:13 volumioecs volumio[1024]: SPOTIFY: received: {"type":"active","data":null} Sep 06 15:34:13 volumioecs volumio[1024]: info: Aligning Spotify Volume to Volumio Volume Sep 06 15:34:13 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:34:13 volumioecs volumio[1024]: info: CorePlayQueue::getTrack 0 Sep 06 15:34:13 volumioecs volumio[1024]: info: Setting Spotify Volume from Volumio: 41 Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 15:34:13 volumioecs go-librespot[1576]: time="2024-09-06T15:34:13-04:00" level=trace msg="emitting websocket event: paused" Sep 06 15:34:13 volumioecs volumio[1024]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:2eItD5YrDMy2vxgBgxpaDy","play_origin":"playlist"}} Sep 06 15:34:13 volumioecs volumio[1024]: info: Spotify is playing in volatile mode Sep 06 15:34:13 volumioecs volumio[1024]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 06 15:34:13 volumioecs volumio[1024]: SPOTIFY: UNSET VOLATILE Sep 06 15:34:13 volumioecs volumio[1024]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":41,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":null,"repeatSingle":false,"updatedb":false,"consume":false} Sep 06 15:34:13 volumioecs volumio[1024]: SPOTIFY: PUSH STATE SPOTIFY Sep 06 15:34:13 volumioecs volumio[1024]: SPOTIFY: {"status":"pause","service":"spop","title":"Monastery Worms","artist":"Cryptivore","album":"Celestial Extinction","albumart":"https://i.scdn.co/image/ab67616d00001e02b63a333ebf8c545e933fa5f7","uri":"spotify:track:2eItD5YrDMy2vxgBgxpaDy","trackType":"spotify","seek":85530,"duration":164,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Sep 06 15:34:13 volumioecs volumio[1024]: info: CoreCommandRouter::servicePushState Sep 06 15:34:13 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:13 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:13 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:13 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: SETTING SPOTIFY VOLUME 41 Sep 06 15:34:15 volumioecs volumio[1024]: info: Sending Spotify command with payload to local API: /player/volume Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=debug msg="update volume to 26869/65535" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=debug msg="handling resume player command from 177d4c2c7b4693890c166b11383a94abd2a15c78" Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":41,"max":100}} Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 41 Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=trace msg="seek to 85530ms (diff: 39ms, samples: 3771873, bytes: 3265859)" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 16666 us, period size = 735 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 30 frames" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=debug msg="resume track at 85491ms" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=trace msg="scheduling prefetch in 49s" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=debug msg="sending successful reply for dealer request" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 15:34:15 volumioecs go-librespot[1576]: time="2024-09-06T15:34:15-04:00" level=trace msg="emitting websocket event: playing" Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2eItD5YrDMy2vxgBgxpaDy","play_origin":"playlist"}} Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: PUSH STATE SPOTIFY Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: {"status":"play","service":"spop","title":"Monastery Worms","artist":"Cryptivore","album":"Celestial Extinction","albumart":"https://i.scdn.co/image/ab67616d00001e02b63a333ebf8c545e933fa5f7","uri":"spotify:track:2eItD5YrDMy2vxgBgxpaDy","trackType":"spotify","seek":85530,"duration":164,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 06 15:34:15 volumioecs volumio[1024]: info: CoreCommandRouter::servicePushState Sep 06 15:34:15 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:15 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:15 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: PUSH STATE SPOTIFY Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: {"status":"play","service":"spop","title":"Monastery Worms","artist":"Cryptivore","album":"Celestial Extinction","albumart":"https://i.scdn.co/image/ab67616d00001e02b63a333ebf8c545e933fa5f7","uri":"spotify:track:2eItD5YrDMy2vxgBgxpaDy","trackType":"spotify","seek":85530,"duration":164,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 06 15:34:15 volumioecs volumio[1024]: info: CoreCommandRouter::servicePushState Sep 06 15:34:15 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:15 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:15 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Sep 06 15:34:19 volumioecs go-librespot[1576]: time="2024-09-06T15:34:19-04:00" level=debug msg="update volume to 26214/65535" Sep 06 15:34:19 volumioecs go-librespot[1576]: time="2024-09-06T15:34:19-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:19 volumioecs go-librespot[1576]: time="2024-09-06T15:34:19-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:19 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":40,"max":100}} Sep 06 15:34:19 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 40 Sep 06 15:34:19 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 40 Sep 06 15:34:19 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume40 Sep 06 15:34:19 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:19 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:19 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:19 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Sep 06 15:34:19 volumioecs go-librespot[1576]: time="2024-09-06T15:34:19-04:00" level=debug msg="update volume to 25558/65535" Sep 06 15:34:19 volumioecs go-librespot[1576]: time="2024-09-06T15:34:19-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:19 volumioecs go-librespot[1576]: time="2024-09-06T15:34:19-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:19 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":39,"max":100}} Sep 06 15:34:19 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 39 Sep 06 15:34:19 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 39 Sep 06 15:34:19 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume39 Sep 06 15:34:19 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:19 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:19 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:19 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 39 Sep 06 15:34:19 volumioecs go-librespot[1576]: time="2024-09-06T15:34:19-04:00" level=debug msg="update volume to 24903/65535" Sep 06 15:34:19 volumioecs go-librespot[1576]: time="2024-09-06T15:34:19-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:19 volumioecs go-librespot[1576]: time="2024-09-06T15:34:19-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:19 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":38,"max":100}} Sep 06 15:34:19 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 38 Sep 06 15:34:19 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 38 Sep 06 15:34:19 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume38 Sep 06 15:34:19 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:19 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:19 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:19 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Sep 06 15:34:20 volumioecs go-librespot[1576]: time="2024-09-06T15:34:20-04:00" level=debug msg="update volume to 24248/65535" Sep 06 15:34:20 volumioecs go-librespot[1576]: time="2024-09-06T15:34:20-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:20 volumioecs go-librespot[1576]: time="2024-09-06T15:34:20-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:20 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":38,"max":100}} Sep 06 15:34:20 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 38 Sep 06 15:34:20 volumioecs go-librespot[1576]: time="2024-09-06T15:34:20-04:00" level=debug msg="update volume to 23592/65535" Sep 06 15:34:20 volumioecs go-librespot[1576]: time="2024-09-06T15:34:20-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:20 volumioecs go-librespot[1576]: time="2024-09-06T15:34:20-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:20 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":36,"max":100}} Sep 06 15:34:20 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 36 Sep 06 15:34:20 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 36 Sep 06 15:34:20 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume36 Sep 06 15:34:20 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:20 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:20 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:20 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Sep 06 15:34:20 volumioecs go-librespot[1576]: time="2024-09-06T15:34:20-04:00" level=debug msg="update volume to 22937/65535" Sep 06 15:34:20 volumioecs go-librespot[1576]: time="2024-09-06T15:34:20-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:20 volumioecs go-librespot[1576]: time="2024-09-06T15:34:20-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:20 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":35,"max":100}} Sep 06 15:34:20 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 35 Sep 06 15:34:20 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 35 Sep 06 15:34:20 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume35 Sep 06 15:34:20 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:20 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:20 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:20 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Sep 06 15:34:21 volumioecs go-librespot[1576]: time="2024-09-06T15:34:21-04:00" level=debug msg="update volume to 18349/65535" Sep 06 15:34:21 volumioecs go-librespot[1576]: time="2024-09-06T15:34:21-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:21 volumioecs go-librespot[1576]: time="2024-09-06T15:34:21-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:21 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":28,"max":100}} Sep 06 15:34:21 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 28 Sep 06 15:34:21 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 28 Sep 06 15:34:21 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume28 Sep 06 15:34:21 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:21 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:21 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:21 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 28 Sep 06 15:34:21 volumioecs go-librespot[1576]: time="2024-09-06T15:34:21-04:00" level=debug msg="update volume to 13107/65535" Sep 06 15:34:21 volumioecs go-librespot[1576]: time="2024-09-06T15:34:21-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:21 volumioecs go-librespot[1576]: time="2024-09-06T15:34:21-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:21 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":20,"max":100}} Sep 06 15:34:21 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 20 Sep 06 15:34:21 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 20 Sep 06 15:34:21 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume20 Sep 06 15:34:21 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:21 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:21 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:21 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Sep 06 15:34:21 volumioecs go-librespot[1576]: time="2024-09-06T15:34:21-04:00" level=debug msg="update volume to 10485/65535" Sep 06 15:34:21 volumioecs go-librespot[1576]: time="2024-09-06T15:34:21-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:21 volumioecs go-librespot[1576]: time="2024-09-06T15:34:21-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:21 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":16,"max":100}} Sep 06 15:34:21 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 16 Sep 06 15:34:21 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 16 Sep 06 15:34:21 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume16 Sep 06 15:34:21 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:21 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:21 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:21 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 16 Sep 06 15:34:22 volumioecs go-librespot[1576]: time="2024-09-06T15:34:22-04:00" level=debug msg="update volume to 5898/65535" Sep 06 15:34:22 volumioecs go-librespot[1576]: time="2024-09-06T15:34:22-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:22 volumioecs go-librespot[1576]: time="2024-09-06T15:34:22-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:22 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":9,"max":100}} Sep 06 15:34:22 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 9 Sep 06 15:34:22 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 9 Sep 06 15:34:22 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume9 Sep 06 15:34:22 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:22 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:22 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:22 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 9 Sep 06 15:34:23 volumioecs go-librespot[1576]: time="2024-09-06T15:34:23-04:00" level=debug msg="update volume to 6553/65535" Sep 06 15:34:23 volumioecs go-librespot[1576]: time="2024-09-06T15:34:23-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:23 volumioecs go-librespot[1576]: time="2024-09-06T15:34:23-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:23 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":10,"max":100}} Sep 06 15:34:23 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 10 Sep 06 15:34:23 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 10 Sep 06 15:34:23 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume10 Sep 06 15:34:23 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:23 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:23 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:23 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Sep 06 15:34:24 volumioecs go-librespot[1576]: time="2024-09-06T15:34:24-04:00" level=debug msg="update volume to 9830/65535" Sep 06 15:34:24 volumioecs go-librespot[1576]: time="2024-09-06T15:34:24-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:24 volumioecs go-librespot[1576]: time="2024-09-06T15:34:24-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:24 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":15,"max":100}} Sep 06 15:34:24 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 15 Sep 06 15:34:24 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 15 Sep 06 15:34:24 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume15 Sep 06 15:34:24 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:24 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:24 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:24 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Sep 06 15:34:24 volumioecs go-librespot[1576]: time="2024-09-06T15:34:24-04:00" level=debug msg="update volume to 14417/65535" Sep 06 15:34:24 volumioecs go-librespot[1576]: time="2024-09-06T15:34:24-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:24 volumioecs go-librespot[1576]: time="2024-09-06T15:34:24-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:24 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":22,"max":100}} Sep 06 15:34:24 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 22 Sep 06 15:34:24 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 22 Sep 06 15:34:24 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume22 Sep 06 15:34:24 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:24 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:24 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:24 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 22 Sep 06 15:34:24 volumioecs go-librespot[1576]: time="2024-09-06T15:34:24-04:00" level=debug msg="update volume to 17039/65535" Sep 06 15:34:24 volumioecs go-librespot[1576]: time="2024-09-06T15:34:24-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:24 volumioecs go-librespot[1576]: time="2024-09-06T15:34:24-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:24 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Sep 06 15:34:24 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Sep 06 15:34:24 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 26 Sep 06 15:34:24 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume26 Sep 06 15:34:24 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:24 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:24 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:24 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 26 Sep 06 15:34:25 volumioecs go-librespot[1576]: time="2024-09-06T15:34:25-04:00" level=debug msg="fetched chunk 10/11, size: 524288" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:25 volumioecs go-librespot[1576]: time="2024-09-06T15:34:25-04:00" level=debug msg="update volume to 22282/65535" Sep 06 15:34:25 volumioecs go-librespot[1576]: time="2024-09-06T15:34:25-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:25 volumioecs go-librespot[1576]: time="2024-09-06T15:34:25-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:25 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":35,"max":100}} Sep 06 15:34:25 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 35 Sep 06 15:34:25 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 35 Sep 06 15:34:25 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume35 Sep 06 15:34:25 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:25 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:25 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:25 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Sep 06 15:34:25 volumioecs go-librespot[1576]: time="2024-09-06T15:34:25-04:00" level=debug msg="update volume to 27524/65535" Sep 06 15:34:25 volumioecs go-librespot[1576]: time="2024-09-06T15:34:25-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:25 volumioecs go-librespot[1576]: time="2024-09-06T15:34:25-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:25 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":42,"max":100}} Sep 06 15:34:25 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 42 Sep 06 15:34:25 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 42 Sep 06 15:34:25 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume42 Sep 06 15:34:25 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:25 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:25 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:25 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Sep 06 15:34:25 volumioecs go-librespot[1576]: time="2024-09-06T15:34:25-04:00" level=debug msg="update volume to 30146/65535" Sep 06 15:34:26 volumioecs go-librespot[1576]: time="2024-09-06T15:34:26-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 06 15:34:26 volumioecs go-librespot[1576]: time="2024-09-06T15:34:26-04:00" level=trace msg="emitting websocket event: volume" Sep 06 15:34:26 volumioecs volumio[1024]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Sep 06 15:34:26 volumioecs volumio[1024]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Sep 06 15:34:26 volumioecs volumio[1024]: info: Setting Volumio Volume from Spotify: 46 Sep 06 15:34:26 volumioecs volumio[1024]: info: VolumeController::SetAlsaVolume46 Sep 06 15:34:26 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:34:26 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:34:26 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:34:26 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Sep 06 15:34:28 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 15:34:28 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 15:34:28 volumioecs volumio[1024]: info: Discovery: Getting this device information Sep 06 15:34:28 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:34:28 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 15:34:38 volumioecs go-librespot[1576]: time="2024-09-06T15:34:38-04:00" level=debug msg="fetched chunk 11/11, size: 512976" uri="spotify:track:2eItD5YrDMy2vxgBgxpaDy" Sep 06 15:34:39 volumioecs volumio[1024]: verbose: New Socket.io Connection to 192.168.1.171 from 192.168.1.5 UA: Mozilla/5.0 (Linux; Android 14; Pixel 7 Build/AP2A.240805.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/129.0.6668.31 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Sep 06 15:34:40 volumioecs volumio[1024]: info: Received Get System Info Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 15:34:40 volumioecs volumio[1024]: info: Discovery: Getting this device information Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetVisibleSources Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 06 15:34:40 volumioecs volumio[1024]: info: Received Get System Info Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 15:34:40 volumioecs volumio[1024]: info: Discovery: Getting this device information Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:34:40 volumioecs volumio[1024]: info: Listing playlists Sep 06 15:34:40 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 06 15:34:46 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetQueue Sep 06 15:34:46 volumioecs volumio[1024]: info: CoreStateMachine::getQueue Sep 06 15:34:46 volumioecs volumio[1024]: info: CorePlayQueue::getQueue Sep 06 15:34:46 volumioecs volumio[1024]: info: CorePlayQueue::getTrack 0 Sep 06 15:34:46 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: mpd , goto Sep 06 15:34:46 volumioecs volumio[1024]: error: Parse List Albums error:null Sep 06 15:35:04 volumioecs go-librespot[1576]: time="2024-09-06T15:35:04-04:00" level=debug msg="prefetching next track" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:04 volumioecs go-librespot[1576]: time="2024-09-06T15:35:04-04:00" level=debug msg="selected format OGG_VORBIS_320 (c0db8222855c5583845b121c3b85c5a64cf35909)" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:04 volumioecs go-librespot[1576]: time="2024-09-06T15:35:04-04:00" level=debug msg="requested aes key for file c0db8222855c5583845b121c3b85c5a64cf35909, gid: 2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:05 volumioecs go-librespot[1576]: time="2024-09-06T15:35:05-04:00" level=debug msg="fetched first chunk of 10, total size is 4970452 bytes" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:05 volumioecs go-librespot[1576]: time="2024-09-06T15:35:05-04:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:05 volumioecs go-librespot[1576]: time="2024-09-06T15:35:05-04:00" level=info msg="prefetched track \"Solemn Desolation\" (duration: 128000ms)" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:05 volumioecs go-librespot[1576]: time="2024-09-06T15:35:05-04:00" level=debug msg="fetched chunk 1/9, size: 524288" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:05 volumioecs go-librespot[1576]: time="2024-09-06T15:35:05-04:00" level=debug msg="fetched chunk 2/9, size: 524288" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:05 volumioecs go-librespot[1576]: time="2024-09-06T15:35:05-04:00" level=debug msg="fetched chunk 3/9, size: 524288" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:27 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 06 15:35:27 volumioecs volumio[1024]: info: CURURI: music-library Sep 06 15:35:27 volumioecs volumio[1024]: error: Failed LSINFO: null Sep 06 15:35:27 volumioecs volumio[1024]: info: Preload queue cleared Sep 06 15:35:33 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 15:35:33 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 15:35:33 volumioecs volumio[1024]: info: Discovery: Getting this device information Sep 06 15:35:33 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:35:33 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 15:35:33 volumioecs volumio[1024]: verbose: New Socket.io Connection to 192.168.1.171:3000 from 192.168.1.5 UA: Dart/3.4 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Sep 06 15:35:33 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:35:33 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Sep 06 15:35:33 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=trace msg="emitting websocket event: not_playing" Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:2eItD5YrDMy2vxgBgxpaDy","play_origin":"playlist"}} Sep 06 15:35:34 volumioecs volumio[1024]: error: Failed to decode event: not_playing Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=trace msg="emitting websocket event: will_play" Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2neN6rUu8FY3blX0dSRxtQ","play_origin":"playlist"}} Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=info msg="loaded track \"Solemn Desolation\" (paused: false, position: 0ms, duration: 128000ms, prefetched: true)" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=trace msg="scheduling prefetch in 97s" Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=trace msg="emitting websocket event: metadata" Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2neN6rUu8FY3blX0dSRxtQ","name":"Solemn Desolation","artist_names":["Cryptivore"],"album_name":"Celestial Extinction","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b63a333ebf8c545e933fa5f7","position":0,"duration":128000,"release_date":"year:2022 month:3 day:24","track_number":7,"disc_number":1}} Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 06 15:35:34 volumioecs go-librespot[1576]: time="2024-09-06T15:35:34-04:00" level=trace msg="emitting websocket event: playing" Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2neN6rUu8FY3blX0dSRxtQ","play_origin":"playlist"}} Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: PUSH STATE SPOTIFY Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: {"status":"play","service":"spop","title":"Solemn Desolation","artist":"Cryptivore","album":"Celestial Extinction","albumart":"https://i.scdn.co/image/ab67616d00001e02b63a333ebf8c545e933fa5f7","uri":"spotify:track:2neN6rUu8FY3blX0dSRxtQ","trackType":"spotify","seek":0,"duration":128,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 06 15:35:34 volumioecs volumio[1024]: info: CoreCommandRouter::servicePushState Sep 06 15:35:34 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:35:34 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:35:34 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: PUSH STATE SPOTIFY Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: {"status":"play","service":"spop","title":"Solemn Desolation","artist":"Cryptivore","album":"Celestial Extinction","albumart":"https://i.scdn.co/image/ab67616d00001e02b63a333ebf8c545e933fa5f7","uri":"spotify:track:2neN6rUu8FY3blX0dSRxtQ","trackType":"spotify","seek":1000,"duration":128,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Sep 06 15:35:34 volumioecs volumio[1024]: info: CoreCommandRouter::servicePushState Sep 06 15:35:34 volumioecs volumio[1024]: info: CoreStateMachine::pushState Sep 06 15:35:34 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 06 15:35:34 volumioecs volumio[1024]: info: CoreCommandRouter::volumioPushState Sep 06 15:35:34 volumioecs volumio[1024]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Sep 06 15:35:35 volumioecs sudo[2112]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 06 15:35:35 volumioecs sudo[2112]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 06 15:35:35 volumioecs sudo[2112]: pam_unix(sudo:session): session closed for user root Sep 06 15:35:35 volumioecs sudo[2114]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 06 15:35:35 volumioecs sudo[2114]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 06 15:35:35 volumioecs sudo[2114]: pam_unix(sudo:session): session closed for user root Sep 06 15:35:35 volumioecs volumio[1024]: verbose: New Socket.io Connection to 192.168.1.171 from 192.168.1.5 UA: Mozilla/5.0 (Linux; Android 14; Pixel 7 Build/AP2A.240805.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/129.0.6668.31 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Sep 06 15:35:35 volumioecs sudo[2118]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 06 15:35:35 volumioecs sudo[2118]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 06 15:35:35 volumioecs sudo[2118]: pam_unix(sudo:session): session closed for user root Sep 06 15:35:35 volumioecs sudo[2120]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 06 15:35:35 volumioecs sudo[2120]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 06 15:35:35 volumioecs sudo[2120]: pam_unix(sudo:session): session closed for user root Sep 06 15:35:35 volumioecs volumio[1024]: verbose: New Socket.io Connection to 192.168.1.171 from 192.168.1.5 UA: Mozilla/5.0 (Linux; Android 14; Pixel 7 Build/AP2A.240805.005; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/129.0.6668.31 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetVisibleSources Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetQueue Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreStateMachine::getQueue Sep 06 15:35:36 volumioecs volumio[1024]: info: CorePlayQueue::getQueue Sep 06 15:35:36 volumioecs volumio[1024]: info: Listing playlists Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 06 15:35:36 volumioecs volumio[1024]: info: Received Get System Info Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 15:35:36 volumioecs volumio[1024]: info: Discovery: Getting this device information Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 06 15:35:36 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 06 15:35:37 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Sep 06 15:35:37 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 06 15:35:37 volumioecs volumio[1024]: info: Received Get System Info Sep 06 15:35:37 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 15:35:37 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 15:35:37 volumioecs volumio[1024]: info: Discovery: Getting this device information Sep 06 15:35:37 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:35:37 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 15:35:38 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 06 15:35:38 volumioecs volumio[1024]: info: Received Get System Info Sep 06 15:35:38 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 06 15:35:38 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 06 15:35:38 volumioecs volumio[1024]: info: Discovery: Getting this device information Sep 06 15:35:38 volumioecs volumio[1024]: info: CoreCommandRouter::volumioGetState Sep 06 15:35:38 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 06 15:35:43 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 06 15:35:43 volumioecs volumio[1024]: info: Preload queue cleared Sep 06 15:35:44 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 06 15:35:44 volumioecs volumio[1024]: info: Preload queue cleared Sep 06 15:35:45 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 06 15:35:45 volumioecs volumio[1024]: info: Preload queue cleared Sep 06 15:35:45 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Sep 06 15:35:46 volumioecs go-librespot[1576]: time="2024-09-06T15:35:46-04:00" level=debug msg="fetched chunk 4/9, size: 524288" uri="spotify:track:2neN6rUu8FY3blX0dSRxtQ" Sep 06 15:35:47 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 06 15:35:47 volumioecs volumio[1024]: info: Preload queue cleared Sep 06 15:35:48 volumioecs volumio[1024]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 06 15:35:48 volumioecs volumio[1024]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 06 15:35:48 volumioecs volumio[1024]: TypeError: Cannot read property 'length' of undefined Sep 06 15:35:48 volumioecs volumio[1024]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Sep 06 15:35:48 volumioecs volumio[1024]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Sep 06 15:35:48 volumioecs volumio[1024]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Sep 06 15:35:48 volumioecs volumio[1024]: at Parser.emit (events.js:400:28) Sep 06 15:35:48 volumioecs volumio[1024]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Sep 06 15:35:48 volumioecs volumio[1024]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Sep 06 15:35:48 volumioecs volumio[1024]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Sep 06 15:35:48 volumioecs volumio[1024]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Sep 06 15:35:48 volumioecs volumio[1024]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Sep 06 15:35:48 volumioecs volumio[1024]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Sep 06 15:35:48 volumioecs volumio[1024]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Sep 06 15:35:48 volumioecs volumio[1024]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Sep 06 15:35:48 volumioecs volumio[1024]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Sep 06 15:35:48 volumioecs volumio[1024]: at IncomingMessage.emit (events.js:412:35) Sep 06 15:35:48 volumioecs volumio[1024]: at endReadableNT (internal/streams/readable.js:1333:12) Sep 06 15:35:48 volumioecs volumio[1024]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Sep 06 15:35:48 volumioecs volumio[1024]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 06 15:35:49 volumioecs sudo[2132]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-06 15:34 Sep 06 15:35:49 volumioecs sudo[2132]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:48:50 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="1049be5fd382035818795b7f5c38e10d"