-- Logs begin at Fri 2024-10-04 22:36:55 CEST, end at Fri 2024-10-04 22:57:18 CEST. -- Oct 04 22:56:03 volumio go-librespot[1784]: time="2024-10-04T22:56:03+02:00" level=debug msg="prefetching next track" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:03 volumio go-librespot[1784]: time="2024-10-04T22:56:03+02:00" level=debug msg="selected format OGG_VORBIS_320 (446a22e1047f7a44728d50c52a885c9f415666d0)" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:03 volumio go-librespot[1784]: time="2024-10-04T22:56:03+02:00" level=debug msg="requested aes key for file 446a22e1047f7a44728d50c52a885c9f415666d0, gid: 1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:03 volumio go-librespot[1784]: time="2024-10-04T22:56:03+02:00" level=debug msg="fetched first chunk of 20, total size is 10239244 bytes" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:03 volumio go-librespot[1784]: time="2024-10-04T22:56:03+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:03 volumio go-librespot[1784]: time="2024-10-04T22:56:03+02:00" level=info msg="prefetched track \"Stasera... Che Sera! - 1991 - Remaster\" (duration: 206657ms)" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:04 volumio go-librespot[1784]: time="2024-10-04T22:56:04+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:04 volumio volumio[1136]: info: CoreCommandRouter::volumioGetQueue Oct 04 22:56:04 volumio volumio[1136]: info: CoreStateMachine::getQueue Oct 04 22:56:04 volumio volumio[1136]: info: CorePlayQueue::getQueue Oct 04 22:56:04 volumio go-librespot[1784]: time="2024-10-04T22:56:04+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:04 volumio go-librespot[1784]: time="2024-10-04T22:56:04+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:12 volumio volumio[1136]: info: CoreCommandRouter::volumioGetState Oct 04 22:56:14 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:14 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:14 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:14 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:14 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:14 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:23 volumio volumio[1136]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 04 22:56:23 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 04 22:56:23 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 04 22:56:23 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 04 22:56:23 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Oct 04 22:56:23 volumio volumio[1136]: info: Received Get System Version Oct 04 22:56:23 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 04 22:56:31 volumio go-librespot[1784]: time="2024-10-04T22:56:31+02:00" level=debug msg="handling play player command from 77ff03ebb67bf60dc23d621fff709e7daedc3d6b" Oct 04 22:56:31 volumio go-librespot[1784]: time="2024-10-04T22:56:31+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:4QEFMzwGf8CGB0wufSuzYv" Oct 04 22:56:31 volumio go-librespot[1784]: time="2024-10-04T22:56:31+02:00" level=trace msg="fetched new page 0 with 87 items (list: 87)" uri="spotify:playlist:4QEFMzwGf8CGB0wufSuzYv" Oct 04 22:56:31 volumio go-librespot[1784]: time="2024-10-04T22:56:31+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:31 volumio go-librespot[1784]: time="2024-10-04T22:56:31+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:31 volumio go-librespot[1784]: time="2024-10-04T22:56:31+02:00" level=trace msg="emitting websocket event: will_play" Oct 04 22:56:31 volumio volumio[1136]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","play_origin":"playlist/ondemand"}} Oct 04 22:56:31 volumio go-librespot[1784]: time="2024-10-04T22:56:31+02:00" level=debug msg="selected format OGG_VORBIS_320 (efb07e177d61202875af78fd3325496e6a2ebf5e)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:31 volumio go-librespot[1784]: time="2024-10-04T22:56:31+02:00" level=debug msg="requested aes key for file efb07e177d61202875af78fd3325496e6a2ebf5e, gid: 5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="fetched first chunk of 23, total size is 11971216 bytes" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=info msg="loaded track \"Telefonami tra vent'anni\" (paused: false, position: 0ms, duration: 281573ms, prefetched: false)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=trace msg="scheduling prefetch in 251s" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=trace msg="emitting websocket event: metadata" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="sending successful reply for dealer request" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=trace msg="emitting websocket event: not_playing" Oct 04 22:56:32 volumio volumio[1136]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","name":"Telefonami tra vent'anni","artist_names":["Lucio Dalla"],"album_name":"The Collection","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02edea47d2491a020eaf1c83ba","position":0,"duration":281573,"release_date":"year:1994 month:7 day:13","track_number":6,"disc_number":1}} Oct 04 22:56:32 volumio volumio[1136]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","play_origin":"playlist/ondemand"}} Oct 04 22:56:32 volumio volumio[1136]: error: Failed to decode event: not_playing Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="resolved autoplay station: spotify:station:playlist:4QEFMzwGf8CGB0wufSuzYv" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="resolved context of track" uri="spotify:station:playlist:4QEFMzwGf8CGB0wufSuzYv" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:playlist:4QEFMzwGf8CGB0wufSuzYv" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=trace msg="emitting websocket event: will_play" Oct 04 22:56:32 volumio volumio[1136]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1uz6If8Tcbjm3xyxQ48IjV","play_origin":"playlist/ondemand"}} Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="selected format OGG_VORBIS_320 (446a22e1047f7a44728d50c52a885c9f415666d0)" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:32 volumio go-librespot[1784]: time="2024-10-04T22:56:32+02:00" level=debug msg="requested aes key for file 446a22e1047f7a44728d50c52a885c9f415666d0, gid: 1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:33 volumio go-librespot[1784]: time="2024-10-04T22:56:33+02:00" level=debug msg="fetched first chunk of 20, total size is 10239244 bytes" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:33 volumio go-librespot[1784]: time="2024-10-04T22:56:33+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:33 volumio go-librespot[1784]: time="2024-10-04T22:56:33+02:00" level=info msg="loaded track \"Stasera... Che Sera! - 1991 - Remaster\" (paused: false, position: 0ms, duration: 206657ms, prefetched: false)" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:33 volumio go-librespot[1784]: time="2024-10-04T22:56:33+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:33 volumio go-librespot[1784]: time="2024-10-04T22:56:33+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:33 volumio go-librespot[1784]: time="2024-10-04T22:56:33+02:00" level=trace msg="scheduling prefetch in 176s" Oct 04 22:56:33 volumio go-librespot[1784]: time="2024-10-04T22:56:33+02:00" level=trace msg="emitting websocket event: metadata" Oct 04 22:56:33 volumio volumio[1136]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1uz6If8Tcbjm3xyxQ48IjV","name":"Stasera... Che Sera! - 1991 - Remaster","artist_names":["Matia Bazar"],"album_name":"Matia Bazar 1 (1991 Remaster)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a411a74516374a3b38a115e0","position":0,"duration":206657,"release_date":"year:1976","track_number":6,"disc_number":1}} Oct 04 22:56:33 volumio go-librespot[1784]: time="2024-10-04T22:56:33+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:34 volumio go-librespot[1784]: time="2024-10-04T22:56:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:34 volumio go-librespot[1784]: time="2024-10-04T22:56:34+02:00" level=trace msg="emitting websocket event: playing" Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1uz6If8Tcbjm3xyxQ48IjV","play_origin":"playlist/ondemand"}} Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: PUSH STATE SPOTIFY Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: {"status":"play","service":"spop","title":"Stasera... Che Sera! - 1991 - Remaster","artist":"Matia Bazar","album":"Matia Bazar 1 (1991 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02a411a74516374a3b38a115e0","uri":"spotify:track:1uz6If8Tcbjm3xyxQ48IjV","trackType":"spotify","seek":0,"duration":206,"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 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::servicePushState Oct 04 22:56:34 volumio volumio[1136]: info: CoreStateMachine::pushState Oct 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::volumioPushState Oct 04 22:56:34 volumio volumio[1136]: info: MRS: Pushing multiroomSync output update for this device Oct 04 22:56:34 volumio volumio[1136]: info: MRS: Pushing multiroomSync output Oct 04 22:56:34 volumio go-librespot[1784]: time="2024-10-04T22:56:34+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: PUSH STATE SPOTIFY Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: {"status":"play","service":"spop","title":"Stasera... Che Sera! - 1991 - Remaster","artist":"Matia Bazar","album":"Matia Bazar 1 (1991 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02a411a74516374a3b38a115e0","uri":"spotify:track:1uz6If8Tcbjm3xyxQ48IjV","trackType":"spotify","seek":0,"duration":206,"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 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::servicePushState Oct 04 22:56:34 volumio volumio[1136]: info: CoreStateMachine::pushState Oct 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::volumioPushState Oct 04 22:56:34 volumio volumio[1136]: info: MRS: Pushing multiroomSync output update for this device Oct 04 22:56:34 volumio volumio[1136]: info: MRS: Pushing multiroomSync output Oct 04 22:56:34 volumio go-librespot[1784]: time="2024-10-04T22:56:34+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:34 volumio go-librespot[1784]: time="2024-10-04T22:56:34+02:00" level=trace msg="emitting websocket event: playing" Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1uz6If8Tcbjm3xyxQ48IjV","play_origin":"playlist/ondemand"}} Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: PUSH STATE SPOTIFY Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: {"status":"play","service":"spop","title":"Stasera... Che Sera! - 1991 - Remaster","artist":"Matia Bazar","album":"Matia Bazar 1 (1991 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02a411a74516374a3b38a115e0","uri":"spotify:track:1uz6If8Tcbjm3xyxQ48IjV","trackType":"spotify","seek":1000,"duration":206,"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 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::servicePushState Oct 04 22:56:34 volumio volumio[1136]: info: CoreStateMachine::pushState Oct 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::volumioPushState Oct 04 22:56:34 volumio volumio[1136]: info: MRS: Pushing multiroomSync output update for this device Oct 04 22:56:34 volumio volumio[1136]: info: MRS: Pushing multiroomSync output Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: PUSH STATE SPOTIFY Oct 04 22:56:34 volumio volumio[1136]: SPOTIFY: {"status":"play","service":"spop","title":"Stasera... Che Sera! - 1991 - Remaster","artist":"Matia Bazar","album":"Matia Bazar 1 (1991 Remaster)","albumart":"https://i.scdn.co/image/ab67616d00001e02a411a74516374a3b38a115e0","uri":"spotify:track:1uz6If8Tcbjm3xyxQ48IjV","trackType":"spotify","seek":1000,"duration":206,"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 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::servicePushState Oct 04 22:56:34 volumio volumio[1136]: info: CoreStateMachine::pushState Oct 04 22:56:34 volumio volumio[1136]: info: CoreCommandRouter::volumioPushState Oct 04 22:56:34 volumio volumio[1136]: info: MRS: Pushing multiroomSync output update for this device Oct 04 22:56:34 volumio volumio[1136]: info: MRS: Pushing multiroomSync output Oct 04 22:56:36 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:36 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:36 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:36 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:36 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:36 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:41 volumio volumio[1136]: info: CoreCommandRouter::volumioGetState Oct 04 22:56:43 volumio volumio[1136]: error: Failed request for metavolumio API Oct 04 22:56:43 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:43 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:43 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:43 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:43 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:43 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:45 volumio go-librespot[1784]: time="2024-10-04T22:56:45+02:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:1uz6If8Tcbjm3xyxQ48IjV" Oct 04 22:56:47 volumio go-librespot[1784]: time="2024-10-04T22:56:47+02:00" level=debug msg="handling play player command from 77ff03ebb67bf60dc23d621fff709e7daedc3d6b" Oct 04 22:56:47 volumio go-librespot[1784]: time="2024-10-04T22:56:47+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:4QEFMzwGf8CGB0wufSuzYv" Oct 04 22:56:47 volumio go-librespot[1784]: time="2024-10-04T22:56:47+02:00" level=trace msg="fetched new page 0 with 87 items (list: 87)" uri="spotify:playlist:4QEFMzwGf8CGB0wufSuzYv" Oct 04 22:56:47 volumio go-librespot[1784]: time="2024-10-04T22:56:47+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:47 volumio go-librespot[1784]: time="2024-10-04T22:56:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:47 volumio go-librespot[1784]: time="2024-10-04T22:56:47+02:00" level=trace msg="emitting websocket event: will_play" Oct 04 22:56:47 volumio volumio[1136]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","play_origin":"playlist/ondemand"}} Oct 04 22:56:47 volumio go-librespot[1784]: time="2024-10-04T22:56:47+02:00" level=debug msg="selected format OGG_VORBIS_320 (efb07e177d61202875af78fd3325496e6a2ebf5e)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:47 volumio go-librespot[1784]: time="2024-10-04T22:56:47+02:00" level=debug msg="requested aes key for file efb07e177d61202875af78fd3325496e6a2ebf5e, gid: 5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="fetched first chunk of 23, total size is 11971216 bytes" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=info msg="loaded track \"Telefonami tra vent'anni\" (paused: false, position: 0ms, duration: 281573ms, prefetched: false)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=trace msg="scheduling prefetch in 251s" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=trace msg="emitting websocket event: metadata" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="sending successful reply for dealer request" Oct 04 22:56:48 volumio volumio[1136]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","name":"Telefonami tra vent'anni","artist_names":["Lucio Dalla"],"album_name":"The Collection","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02edea47d2491a020eaf1c83ba","position":0,"duration":281573,"release_date":"year:1994 month:7 day:13","track_number":6,"disc_number":1}} Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=trace msg="emitting websocket event: playing" Oct 04 22:56:48 volumio volumio[1136]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","play_origin":"playlist/ondemand"}} Oct 04 22:56:48 volumio volumio[1136]: SPOTIFY: PUSH STATE SPOTIFY Oct 04 22:56:48 volumio volumio[1136]: SPOTIFY: {"status":"play","service":"spop","title":"Telefonami tra vent'anni","artist":"Lucio Dalla","album":"The Collection","albumart":"https://i.scdn.co/image/ab67616d00001e02edea47d2491a020eaf1c83ba","uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","trackType":"spotify","seek":0,"duration":281,"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 04 22:56:48 volumio volumio[1136]: info: CoreCommandRouter::servicePushState Oct 04 22:56:48 volumio volumio[1136]: info: CoreStateMachine::pushState Oct 04 22:56:48 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 22:56:48 volumio volumio[1136]: info: CoreCommandRouter::volumioPushState Oct 04 22:56:48 volumio volumio[1136]: info: MRS: Pushing multiroomSync output update for this device Oct 04 22:56:48 volumio volumio[1136]: info: MRS: Pushing multiroomSync output Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="handling play player command from 77ff03ebb67bf60dc23d621fff709e7daedc3d6b" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:4QEFMzwGf8CGB0wufSuzYv" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=trace msg="fetched new page 0 with 87 items (list: 87)" uri="spotify:playlist:4QEFMzwGf8CGB0wufSuzYv" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:48 volumio volumio[1136]: SPOTIFY: PUSH STATE SPOTIFY Oct 04 22:56:48 volumio volumio[1136]: SPOTIFY: {"status":"play","service":"spop","title":"Telefonami tra vent'anni","artist":"Lucio Dalla","album":"The Collection","albumart":"https://i.scdn.co/image/ab67616d00001e02edea47d2491a020eaf1c83ba","uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","trackType":"spotify","seek":1000,"duration":281,"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 04 22:56:48 volumio volumio[1136]: info: CoreCommandRouter::servicePushState Oct 04 22:56:48 volumio volumio[1136]: info: CoreStateMachine::pushState Oct 04 22:56:48 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 22:56:48 volumio volumio[1136]: info: CoreCommandRouter::volumioPushState Oct 04 22:56:48 volumio volumio[1136]: info: MRS: Pushing multiroomSync output update for this device Oct 04 22:56:48 volumio volumio[1136]: info: MRS: Pushing multiroomSync output Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=trace msg="emitting websocket event: will_play" Oct 04 22:56:48 volumio volumio[1136]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","play_origin":"playlist/ondemand"}} Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="selected format OGG_VORBIS_320 (efb07e177d61202875af78fd3325496e6a2ebf5e)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="requested aes key for file efb07e177d61202875af78fd3325496e6a2ebf5e, gid: 5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:48 volumio go-librespot[1784]: time="2024-10-04T22:56:48+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=debug msg="fetched first chunk of 23, total size is 11971216 bytes" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=info msg="loaded track \"Telefonami tra vent'anni\" (paused: false, position: 1ms, duration: 281573ms, prefetched: false)" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=trace msg="scheduling prefetch in 251s" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=trace msg="emitting websocket event: metadata" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=debug msg="sending successful reply for dealer request" Oct 04 22:56:49 volumio volumio[1136]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","name":"Telefonami tra vent'anni","artist_names":["Lucio Dalla"],"album_name":"The Collection","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02edea47d2491a020eaf1c83ba","position":1,"duration":281573,"release_date":"year:1994 month:7 day:13","track_number":6,"disc_number":1}} Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=trace msg="emitting websocket event: playing" Oct 04 22:56:49 volumio volumio[1136]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","play_origin":"playlist/ondemand"}} Oct 04 22:56:49 volumio volumio[1136]: SPOTIFY: PUSH STATE SPOTIFY Oct 04 22:56:49 volumio volumio[1136]: SPOTIFY: {"status":"play","service":"spop","title":"Telefonami tra vent'anni","artist":"Lucio Dalla","album":"The Collection","albumart":"https://i.scdn.co/image/ab67616d00001e02edea47d2491a020eaf1c83ba","uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","trackType":"spotify","seek":1,"duration":281,"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 04 22:56:49 volumio volumio[1136]: info: CoreCommandRouter::servicePushState Oct 04 22:56:49 volumio volumio[1136]: info: CoreStateMachine::pushState Oct 04 22:56:49 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 04 22:56:49 volumio volumio[1136]: info: CoreCommandRouter::volumioPushState Oct 04 22:56:49 volumio volumio[1136]: info: MRS: Pushing multiroomSync output update for this device Oct 04 22:56:49 volumio volumio[1136]: info: MRS: Pushing multiroomSync output Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:49 volumio volumio[1136]: SPOTIFY: PUSH STATE SPOTIFY Oct 04 22:56:49 volumio volumio[1136]: SPOTIFY: {"status":"play","service":"spop","title":"Telefonami tra vent'anni","artist":"Lucio Dalla","album":"The Collection","albumart":"https://i.scdn.co/image/ab67616d00001e02edea47d2491a020eaf1c83ba","uri":"spotify:track:5i8zNoNzfUPmh1NErsD6Xg","trackType":"spotify","seek":1,"duration":281,"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 04 22:56:49 volumio volumio[1136]: info: CoreCommandRouter::servicePushState Oct 04 22:56:49 volumio volumio[1136]: info: CoreStateMachine::pushState Oct 04 22:56:49 volumio volumio[1136]: info: CoreCommandRouter::volumioPushState Oct 04 22:56:49 volumio volumio[1136]: info: MRS: Pushing multiroomSync output update for this device Oct 04 22:56:49 volumio volumio[1136]: info: MRS: Pushing multiroomSync output Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:49 volumio go-librespot[1784]: time="2024-10-04T22:56:49+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:56:50 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:50 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:50 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:50 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:50 volumio volumio[1136]: info: Executing endpoint metavolumio Oct 04 22:56:50 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 04 22:56:50 volumio volumio[1136]: error: Failed request for metavolumio API Oct 04 22:56:55 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 04 22:56:55 volumio volumio[1136]: info: Preload queue cleared Oct 04 22:57:01 volumio go-librespot[1784]: time="2024-10-04T22:57:01+02:00" level=debug msg="fetched chunk 4/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:57:02 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 04 22:57:02 volumio volumio[1136]: info: Preload queue cleared Oct 04 22:57:03 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 04 22:57:05 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 04 22:57:05 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 04 22:57:06 volumio volumio[1136]: info: Preload queue cleared Oct 04 22:57:06 volumio volumio[1136]: info: Preload queue cleared Oct 04 22:57:06 volumio volumio[1136]: info: Preload queue cleared Oct 04 22:57:13 volumio go-librespot[1784]: time="2024-10-04T22:57:13+02:00" level=debug msg="fetched chunk 5/22, size: 524288" uri="spotify:track:5i8zNoNzfUPmh1NErsD6Xg" Oct 04 22:57:18 volumio volumio[1136]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 04 22:57:18 volumio volumio[1136]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 22:57:18 volumio volumio[1136]: TypeError: Cannot read property 'length' of undefined Oct 04 22:57:18 volumio volumio[1136]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Oct 04 22:57:18 volumio volumio[1136]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Oct 04 22:57:18 volumio volumio[1136]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Oct 04 22:57:18 volumio volumio[1136]: at Parser.emit (events.js:400:28) Oct 04 22:57:18 volumio volumio[1136]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Oct 04 22:57:18 volumio volumio[1136]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Oct 04 22:57:18 volumio volumio[1136]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Oct 04 22:57:18 volumio volumio[1136]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Oct 04 22:57:18 volumio volumio[1136]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Oct 04 22:57:18 volumio volumio[1136]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Oct 04 22:57:18 volumio volumio[1136]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Oct 04 22:57:18 volumio volumio[1136]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Oct 04 22:57:18 volumio volumio[1136]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Oct 04 22:57:18 volumio volumio[1136]: at IncomingMessage.emit (events.js:412:35) Oct 04 22:57:18 volumio volumio[1136]: at endReadableNT (internal/streams/readable.js:1333:12) Oct 04 22:57:18 volumio volumio[1136]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Oct 04 22:57:18 volumio volumio[1136]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 04 22:57:18 volumio sudo[3031]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-04 22:56 Oct 04 22:57:18 volumio sudo[3031]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:33:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ee834e1c2a28de3c5d8c48611ecf1167"