-- Logs begin at Thu 2019-02-14 12:11:58 IST, end at Sun 2025-06-08 20:16:35 IDT. -- Jun 08 20:15:02 gnusmos volumio[1203]: info: Jun 08 20:15:02 gnusmos volumio[1203]: ---------------------------- MPD announces system playlist update Jun 08 20:15:02 gnusmos volumio[1203]: info: Ignoring MPD Status Update Jun 08 20:15:02 gnusmos volumio[1203]: info: Jun 08 20:15:02 gnusmos volumio[1203]: ---------------------------- MPD announces state update: player Jun 08 20:15:02 gnusmos volumio[1203]: info: ControllerMpd::getState Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand status Jun 08 20:15:02 gnusmos volumio[1203]: info: Jun 08 20:15:02 gnusmos volumio[1203]: ---------------------------- MPD announces system playlist update Jun 08 20:15:02 gnusmos volumio[1203]: info: Ignoring MPD Status Update Jun 08 20:15:02 gnusmos volumio[1203]: info: Jun 08 20:15:02 gnusmos volumio[1203]: ---------------------------- MPD announces state update: player Jun 08 20:15:02 gnusmos volumio[1203]: info: ControllerMpd::getState Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand status Jun 08 20:15:02 gnusmos volumio[1203]: info: Jun 08 20:15:02 gnusmos volumio[1203]: ---------------------------- MPD announces system playlist update Jun 08 20:15:02 gnusmos volumio[1203]: info: Ignoring MPD Status Update Jun 08 20:15:02 gnusmos volumio[1203]: info: Jun 08 20:15:02 gnusmos volumio[1203]: ---------------------------- MPD announces state update: player Jun 08 20:15:02 gnusmos volumio[1203]: info: ControllerMpd::getState Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand status Jun 08 20:15:02 gnusmos volumio[1203]: info: ------------------------------ 3ms Jun 08 20:15:02 gnusmos volumio[1203]: info: sendMpdCommand status took 3 milliseconds Jun 08 20:15:02 gnusmos volumio[1203]: info: ------------------------------ 3ms Jun 08 20:15:02 gnusmos volumio[1203]: info: sendMpdCommand status took 1 milliseconds Jun 08 20:15:02 gnusmos volumio[1203]: info: ------------------------------ 1ms Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::parseState Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::parseState Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 08 20:15:02 gnusmos volumio[1203]: info: sendMpdCommand status took 1 milliseconds Jun 08 20:15:02 gnusmos volumio[1203]: info: sendMpdCommand playlistinfo took 1 milliseconds Jun 08 20:15:02 gnusmos volumio[1203]: info: sendMpdCommand playlistinfo took 1 milliseconds Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::parseState Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::parseTrackInfo Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::parseTrackInfo Jun 08 20:15:02 gnusmos volumio[1203]: info: ControllerMpd::pushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:02 gnusmos volumio[1203]: verbose: STATE SERVICE {"status":"play","position":0,"seek":100239,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Rodney Jordan - The Storm Will Pass","artist":"Jazz24","album":null,"uri":"https://live.amperwave.net/direct/ppm-jazz24mp3-ibc1","trackType":""} Jun 08 20:15:02 gnusmos volumio[1203]: verbose: CURRENT POSITION 0 Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::syncState stateService play Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::syncState currentStatus play Jun 08 20:15:02 gnusmos volumio[1203]: info: Received an update from plugin. extracting info from payload Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:02 gnusmos volumio[1203]: info: ControllerMpd::pushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:02 gnusmos volumio[1203]: verbose: STATE SERVICE {"status":"play","position":0,"seek":100239,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Rodney Jordan - The Storm Will Pass","artist":"Jazz24","album":null,"uri":"https://live.amperwave.net/direct/ppm-jazz24mp3-ibc1","trackType":""} Jun 08 20:15:02 gnusmos volumio[1203]: verbose: CURRENT POSITION 0 Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::syncState stateService play Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::syncState currentStatus play Jun 08 20:15:02 gnusmos volumio[1203]: info: Received an update from plugin. extracting info from payload Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:02 gnusmos volumio[1203]: info: ------------------------------ 17ms Jun 08 20:15:02 gnusmos volumio[1203]: info: ------------------------------ 17ms Jun 08 20:15:02 gnusmos volumio[1203]: info: sendMpdCommand playlistinfo took 13 milliseconds Jun 08 20:15:02 gnusmos volumio[1203]: verbose: ControllerMpd::parseTrackInfo Jun 08 20:15:02 gnusmos volumio[1203]: info: ControllerMpd::pushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:02 gnusmos volumio[1203]: verbose: STATE SERVICE {"status":"play","position":0,"seek":100239,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Rodney Jordan - The Storm Will Pass","artist":"Jazz24","album":null,"uri":"https://live.amperwave.net/direct/ppm-jazz24mp3-ibc1","trackType":""} Jun 08 20:15:02 gnusmos volumio[1203]: verbose: CURRENT POSITION 0 Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::syncState stateService play Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::syncState currentStatus play Jun 08 20:15:02 gnusmos volumio[1203]: info: Received an update from plugin. extracting info from payload Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:02 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:02 gnusmos volumio[1203]: info: ------------------------------ 21ms Jun 08 20:15:02 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:02 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:02 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:02 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:02 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:02 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:03 gnusmos go-librespot[1403]: time="2025-06-08T20:15:03+03:00" level=debug msg="obtained new client token: AADfESN/XePDLO8NB5SaFr/jOWO8JW4LwvpeHgn3AlgV9Fp5UvPyWlMtzuYJ48VvTwPVjot/5AuIR16jZo+ENGbNAnfKSuOM+LFlYfJ2KJXwNOznOqB/5KJq15RMWQVA41GT6QrZ+vTFzuKQ13MndwpN2WdZVS5ThY3YA4gMhi8ecu2aoYG1qL6BEKKCqgfZvhFJrRPenwWRRt+mkSW0crwcl11EMM+n/bD8OJEjrKA0jB+1QvPctCFr3A==" Jun 08 20:15:03 gnusmos go-librespot[1403]: time="2025-06-08T20:15:03+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Jun 08 20:15:03 gnusmos go-librespot[1403]: time="2025-06-08T20:15:03+03:00" level=debug msg="completed keyexchange" Jun 08 20:15:03 gnusmos go-librespot[1403]: time="2025-06-08T20:15:03+03:00" level=debug msg="completed challenge" Jun 08 20:15:03 gnusmos go-librespot[1403]: time="2025-06-08T20:15:03+03:00" level=error msg="failed creating new session for kn511wtrxl4mf6avna0r9ydz0 from GOGO_MINI" error="failed authenticating accesspoint with blob: failed authenticating: accesspoint login failed: BadCredentials " Jun 08 20:15:03 gnusmos go-librespot[1403]: time="2025-06-08T20:15:03+03:00" level=info msg="refused zeroconf user kn511wtrxl4mf6avna0r9ydz0 from GOGO_MINI" Jun 08 20:15:06 gnusmos go-librespot[1403]: time="2025-06-08T20:15:06+03:00" level=debug msg="obtained new client token: AAAiSnGya48Q9eyp87QpG7J2WDrugkbJTkKb+ZUSPI8uGb44F+wpFduXOpShVswX4uVwcj+KOieZBORd4r2CoCtmqp3fpvMX2w0e0iHosiHSlT1XlepgwZ3nW9LfOMtlgEjDoqfFf9aXyVG+lCUKaSjKIbgDPvXC+NQXdPX5ZSeC2Quc3DjrMharD4F+qyj5st69L7lsf0Yjnmby5plWbY90i/IPEdhHXgjcqEJ5YTDkIY/+sDh4D6SFlQ==" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="completed keyexchange" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="completed challenge" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=info msg="authenticated AP as kn511wtrxl4mf6avna0r9ydz0" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=info msg="authenticated Login5 as kn511wtrxl4mf6avna0r9ydz0" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=info msg="accepted zeroconf user kn511wtrxl4mf6avna0r9ydz0 from GOGO_MINI" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="dealer connection opened" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=trace msg="starting accesspoint recv loop" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=trace msg="starting dealer recv loop" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=trace msg="received accesspoint ping" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="received connection id: YTlhMjJlMzItZDY3My00OTMwLTg5ODItNzkyZWVhYmY5Y2E3K2RlYWxlcit0Y3A6Ly8wYWNhNDAxMS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNjU2NDFGQkM1Mjk5N0E0M0VGNjZGNkZCNTI5RkQxQ0IwQkVGOURCRTYwQ0VBQ0IwRjVGQkYxNjRDNTczNjk4QQ==" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=trace msg="received accesspoint pong ack" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="put connect state because NEW_DEVICE" Jun 08 20:15:07 gnusmos go-librespot[1403]: time="2025-06-08T20:15:07+03:00" level=debug msg="handling transfer player command from da68c219a8619180a5f96ccd75801b8d86538cb5" Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E8FY2kq5bkZpk" Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E8FY2kq5bkZpk" Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=debug msg="loading track (paused: false, position: 22396ms)" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=trace msg="emitting websocket event: will_play" Jun 08 20:15:08 gnusmos volumio[1203]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4d3UnYs8dRDDd93MVaoj74","play_origin":"playlist"}} Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=debug msg="selected format OGG_VORBIS_320 (4c1e8c0846194be22abfc1d341558b2065c1d0b9)" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=debug msg="requested aes key for file 4c1e8c0846194be22abfc1d341558b2065c1d0b9, gid: 4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1690" Jun 08 20:15:08 gnusmos go-librespot[1403]: time="2025-06-08T20:15:08+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1289" Jun 08 20:15:10 gnusmos go-librespot[1403]: time="2025-06-08T20:15:10+03:00" level=debug msg="fetched first chunk of 17, total size is 8544456 bytes" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:12 gnusmos go-librespot[1403]: time="2025-06-08T20:15:12+03:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=trace msg="seek to 22396ms (diff: 98ms, samples: 987663, bytes: 906439)" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=debug msg="created new output device" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed setting stream for spotify:track:4d3UnYs8dRDDd93MVaoj74: ALSA error at snd_pcm_open: Device or resource busy" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=info msg="playback was transferred to GOGO_MINI" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=trace msg="closed output device because of stop command" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=debug msg="put connect state inactive" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=trace msg="emitting websocket event: inactive" Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=trace msg="emitting websocket event: stopped" Jun 08 20:15:13 gnusmos volumio[1203]: SPOTIFY: received: {"type":"inactive","data":null} Jun 08 20:15:13 gnusmos volumio[1203]: error: Failed to decode event: inactive Jun 08 20:15:13 gnusmos volumio[1203]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Jun 08 20:15:13 gnusmos volumio[1203]: SPOTIFY: PUSH STATE SPOTIFY Jun 08 20:15:13 gnusmos volumio[1203]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 08 20:15:13 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:13 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:13 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:15:13 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:13 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:13 gnusmos volumio[1203]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current mpd Received spop Jun 08 20:15:13 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:13 gnusmos go-librespot[1403]: time="2025-06-08T20:15:13+03:00" level=debug msg="dealer recv loop stopped" Jun 08 20:15:14 gnusmos go-librespot[1403]: time="2025-06-08T20:15:14+03:00" level=debug msg="fetched chunk 4/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::volumioStop Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreStateMachine::stop Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreStateMachine::stPlaybackTimer Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreStateMachine::updateTrackBlock Jun 08 20:15:20 gnusmos volumio[1203]: info: CorePlayQueue::getTrackBlock Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreStateMachine::serviceStop Jun 08 20:15:20 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::serviceStop Jun 08 20:15:20 gnusmos volumio[1203]: info: [1749402920376] ControllerWebradio::stop Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand stop Jun 08 20:15:20 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:20 gnusmos volumio[1203]: info: sendMpdCommand stop took 37 milliseconds Jun 08 20:15:20 gnusmos volumio[1203]: info: Jun 08 20:15:20 gnusmos volumio[1203]: ---------------------------- MPD announces state update: player Jun 08 20:15:20 gnusmos volumio[1203]: info: ControllerMpd::getState Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand status Jun 08 20:15:20 gnusmos volumio[1203]: info: Jun 08 20:15:20 gnusmos volumio[1203]: ---------------------------- MPD announces state update: player Jun 08 20:15:20 gnusmos volumio[1203]: info: ControllerMpd::getState Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand status Jun 08 20:15:20 gnusmos volumio[1203]: info: Jun 08 20:15:20 gnusmos volumio[1203]: ---------------------------- MPD announces state update: player Jun 08 20:15:20 gnusmos volumio[1203]: info: ControllerMpd::getState Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand status Jun 08 20:15:20 gnusmos volumio[1203]: info: sendMpdCommand status took 1 milliseconds Jun 08 20:15:20 gnusmos volumio[1203]: info: sendMpdCommand status took 0 milliseconds Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::parseState Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::parseState Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 08 20:15:20 gnusmos volumio[1203]: info: sendMpdCommand status took 1 milliseconds Jun 08 20:15:20 gnusmos volumio[1203]: info: sendMpdCommand playlistinfo took 1 milliseconds Jun 08 20:15:20 gnusmos volumio[1203]: info: sendMpdCommand playlistinfo took 1 milliseconds Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::parseState Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::parseTrackInfo Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::parseTrackInfo Jun 08 20:15:20 gnusmos volumio[1203]: info: ControllerMpd::pushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:20 gnusmos volumio[1203]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Jun 08 20:15:20 gnusmos volumio[1203]: info: ControllerMpd::pushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:20 gnusmos volumio[1203]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Jun 08 20:15:20 gnusmos volumio[1203]: info: ------------------------------ 10ms Jun 08 20:15:20 gnusmos volumio[1203]: info: ------------------------------ 9ms Jun 08 20:15:20 gnusmos volumio[1203]: info: sendMpdCommand playlistinfo took 8 milliseconds Jun 08 20:15:20 gnusmos volumio[1203]: verbose: ControllerMpd::parseTrackInfo Jun 08 20:15:20 gnusmos volumio[1203]: info: ControllerMpd::pushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:15:20 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:20 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:20 gnusmos volumio[1203]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Jun 08 20:15:20 gnusmos volumio[1203]: info: ------------------------------ 13ms Jun 08 20:15:20 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:20 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:20 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:23 gnusmos ntpd[990]: Soliciting pool server 2a05:f480:2c00:1d51:9f31:83c:284a:2948 Jun 08 20:15:26 gnusmos go-librespot[1403]: time="2025-06-08T20:15:26+03:00" level=debug msg="obtained new client token: AADWUjfM8SEEM5f06MTQmQxhQVoABZ0GmIoZ2AZZpmqds2IOkUaaHxALha/u4wTNDuSXtFSuTx8L+iHFKZFK9fKhT4FSgEfg4SpwJpADGIW+hte3KcI+TyKaJZG4IHsnZqbuD+dlqlJWI0r+sCKCPC9LhzKSaaet/b/DWyk9Px6olbBu+gmHbqW2bvH/1HmpfxiqgW4TPgISiCWKpDmcP6vlVP8rz89i1j74d4DlM4EdRuhfRLhf3VgO1Q==" Jun 08 20:15:26 gnusmos go-librespot[1403]: time="2025-06-08T20:15:26+03:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Jun 08 20:15:26 gnusmos go-librespot[1403]: time="2025-06-08T20:15:26+03:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="completed keyexchange" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="completed challenge" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=info msg="authenticated AP as kn511wtrxl4mf6avna0r9ydz0" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=info msg="authenticated Login5 as kn511wtrxl4mf6avna0r9ydz0" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=info msg="accepted zeroconf user kn511wtrxl4mf6avna0r9ydz0 from GOGO_MINI" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="dealer connection opened" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=trace msg="starting accesspoint recv loop" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=trace msg="starting dealer recv loop" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=trace msg="received accesspoint ping" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="received connection id: MjE3NzBkNTEtZDViMS00OGZmLWJlNzYtMmNiYTQ0MzcwYzgyK2RlYWxlcit0Y3A6Ly8wYWNhNDIyYi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNTI4QjcxNTcyMjI4QzE4NTNERkJBMTU1M0I3QkE0M0ZENTY4NzZFNjhGN0ZCMzU3N0MxQzdBMjBDODNGNkM3Mg==" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=trace msg="received accesspoint pong ack" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="put connect state because NEW_DEVICE" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="handling transfer player command from da68c219a8619180a5f96ccd75801b8d86538cb5" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E8FY2kq5bkZpk" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E8FY2kq5bkZpk" Jun 08 20:15:27 gnusmos go-librespot[1403]: time="2025-06-08T20:15:27+03:00" level=debug msg="loading track (paused: false, position: 35109ms)" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=trace msg="emitting websocket event: will_play" Jun 08 20:15:28 gnusmos volumio[1203]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4d3UnYs8dRDDd93MVaoj74","play_origin":"playlist"}} Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="selected format OGG_VORBIS_320 (4c1e8c0846194be22abfc1d341558b2065c1d0b9)" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="requested aes key for file 4c1e8c0846194be22abfc1d341558b2065c1d0b9, gid: 4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1690" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1289" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="fetched first chunk of 17, total size is 8544456 bytes" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:28 gnusmos ntpd[990]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="fetched chunk 4/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=trace msg="seek to 35109ms (diff: 124ms, samples: 1548306, bytes: 1498201)" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:28 gnusmos go-librespot[1403]: time="2025-06-08T20:15:28+03:00" level=debug msg="created new output device" Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=info msg="loaded track \"Wildcard (feat. Sidnie Tipton)\" (paused: false, position: 35109ms, duration: 189375ms, prefetched: false)" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=trace msg="scheduling prefetch in 124s" Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=trace msg="emitting websocket event: metadata" Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=trace msg="emitting websocket event: active" Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=debug msg="sending successful reply for dealer request" Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4d3UnYs8dRDDd93MVaoj74","name":"Wildcard (feat. Sidnie Tipton)","artist_names":["KSHMR","Sidnie Tipton"],"album_name":"Wildcard (feat. Sidnie Tipton)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a765bcee7ae12e7c09523f3e","position":35109,"duration":189375,"release_date":"year:2016 month:4 day:8","track_number":1,"disc_number":1}} Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: received: {"type":"active","data":null} Jun 08 20:15:29 gnusmos volumio[1203]: info: Aligning Spotify Volume to Volumio Volume Jun 08 20:15:29 gnusmos volumio[1203]: info: CoreCommandRouter::volumioGetState Jun 08 20:15:29 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:29 gnusmos volumio[1203]: info: Setting Spotify Volume from Volumio: 100 Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=trace msg="emitting websocket event: playing" Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4d3UnYs8dRDDd93MVaoj74","play_origin":"playlist"}} Jun 08 20:15:29 gnusmos volumio[1203]: info: Spotify is playing in volatile mode Jun 08 20:15:29 gnusmos volumio[1203]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: UNSET VOLATILE Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: {"status":"stop","position":0,"title":"Jazz24","artist":"","albumart":"https://radio-directory.firebaseapp.com/volumio/src/images/radio-thumbnails/Jazz24.jpg","uri":"https://live.amperwave.net/direct/ppm-jazz24mp3-ibc1","trackType":"webradio","seek":1368,"samplerate":"","bitdepth":"","channels":0,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"webradio","updatedb":false,"volatile":false,"service":"webradio"} Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: PUSH STATE SPOTIFY Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: {"status":"play","service":"spop","title":"Wildcard (feat. Sidnie Tipton)","artist":"KSHMR, Sidnie Tipton","album":"Wildcard (feat. Sidnie Tipton)","albumart":"https://i.scdn.co/image/ab67616d00001e02a765bcee7ae12e7c09523f3e","uri":"spotify:track:4d3UnYs8dRDDd93MVaoj74","trackType":"spotify","seek":35109,"duration":189,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 08 20:15:29 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:29 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:29 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:15:29 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:29 gnusmos go-librespot[1403]: time="2025-06-08T20:15:29+03:00" level=debug msg="fetched chunk 5/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: PUSH STATE SPOTIFY Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: {"status":"play","service":"spop","title":"Wildcard (feat. Sidnie Tipton)","artist":"KSHMR, Sidnie Tipton","album":"Wildcard (feat. Sidnie Tipton)","albumart":"https://i.scdn.co/image/ab67616d00001e02a765bcee7ae12e7c09523f3e","uri":"spotify:track:4d3UnYs8dRDDd93MVaoj74","trackType":"spotify","seek":35109,"duration":189,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 08 20:15:29 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:29 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:29 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:29 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:30 gnusmos go-librespot[1403]: time="2025-06-08T20:15:30+03:00" level=debug msg="fetched chunk 6/16, size: 524288" uri="spotify:track:4d3UnYs8dRDDd93MVaoj74" Jun 08 20:15:30 gnusmos volumio[1203]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Jun 08 20:15:30 gnusmos volumio[1203]: info: Sending Spotify command with payload to local API: /player/volume Jun 08 20:15:30 gnusmos go-librespot[1403]: time="2025-06-08T20:15:30+03:00" level=debug msg="update volume to 65535/65535" Jun 08 20:15:31 gnusmos go-librespot[1403]: time="2025-06-08T20:15:31+03:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 08 20:15:31 gnusmos go-librespot[1403]: time="2025-06-08T20:15:31+03:00" level=trace msg="emitting websocket event: volume" Jun 08 20:15:31 gnusmos volumio[1203]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Jun 08 20:15:31 gnusmos volumio[1203]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="handling play player command from da68c219a8619180a5f96ccd75801b8d86538cb5" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E8FY2kq5bkZpk" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E8FY2kq5bkZpk" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=trace msg="emitting websocket event: will_play" Jun 08 20:15:35 gnusmos volumio[1203]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","play_origin":"playlist"}} Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="selected format OGG_VORBIS_320 (9833a51fa74a3271b2b39522341f4c3d303edfbe)" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="requested aes key for file 9833a51fa74a3271b2b39522341f4c3d303edfbe, gid: 3MOECVkNshqHYTPt5DZcdN" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="fetched first chunk of 20, total size is 10144784 bytes" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=info msg="loaded track \"Five More Hours\" (paused: false, position: 0ms, duration: 211975ms, prefetched: false)" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=trace msg="scheduling prefetch in 182s" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=trace msg="emitting websocket event: metadata" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="sending successful reply for dealer request" Jun 08 20:15:35 gnusmos volumio[1203]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","name":"Five More Hours","artist_names":["Deorro","Chris Brown"],"album_name":"Good Evening","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02fe3951b474a76b0f25e3c760","position":0,"duration":211975,"release_date":"year:2017 month:3 day:31","track_number":26,"disc_number":1}} Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:15:35 gnusmos go-librespot[1403]: time="2025-06-08T20:15:35+03:00" level=trace msg="emitting websocket event: playing" Jun 08 20:15:35 gnusmos volumio[1203]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","play_origin":"playlist"}} Jun 08 20:15:35 gnusmos volumio[1203]: SPOTIFY: PUSH STATE SPOTIFY Jun 08 20:15:35 gnusmos volumio[1203]: SPOTIFY: {"status":"play","service":"spop","title":"Five More Hours","artist":"Deorro, Chris Brown","album":"Good Evening","albumart":"https://i.scdn.co/image/ab67616d00001e02fe3951b474a76b0f25e3c760","uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","trackType":"spotify","seek":0,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 08 20:15:35 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:35 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:35 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:15:35 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:35 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:36 gnusmos go-librespot[1403]: time="2025-06-08T20:15:36+03:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:15:36 gnusmos volumio[1203]: SPOTIFY: PUSH STATE SPOTIFY Jun 08 20:15:36 gnusmos volumio[1203]: SPOTIFY: {"status":"play","service":"spop","title":"Five More Hours","artist":"Deorro, Chris Brown","album":"Good Evening","albumart":"https://i.scdn.co/image/ab67616d00001e02fe3951b474a76b0f25e3c760","uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","trackType":"spotify","seek":0,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 08 20:15:36 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:36 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:36 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:36 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=info msg="playback was transferred to GOGO_MINI" Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1271" Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=trace msg="closed output device because of stop command" Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 250" Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1664" Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=debug msg="put connect state inactive" Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=trace msg="emitting websocket event: inactive" Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=trace msg="emitting websocket event: stopped" Jun 08 20:15:45 gnusmos volumio[1203]: SPOTIFY: received: {"type":"inactive","data":null} Jun 08 20:15:45 gnusmos volumio[1203]: error: Failed to decode event: inactive Jun 08 20:15:45 gnusmos volumio[1203]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Jun 08 20:15:45 gnusmos volumio[1203]: SPOTIFY: PUSH STATE SPOTIFY Jun 08 20:15:45 gnusmos volumio[1203]: SPOTIFY: {"status":"stop","service":"spop","title":"Five More Hours","artist":"Deorro, Chris Brown","album":"Good Evening","albumart":"https://i.scdn.co/image/ab67616d00001e02fe3951b474a76b0f25e3c760","uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","trackType":"spotify","seek":10000,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 08 20:15:45 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:15:45 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:15:45 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:15:45 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:15:45 gnusmos volumio[1203]: info: CorePlayQueue::getTrack 0 Jun 08 20:15:45 gnusmos volumio[1203]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received spop Jun 08 20:15:45 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=debug msg="dealer connection closed" Jun 08 20:15:45 gnusmos go-librespot[1403]: time="2025-06-08T20:15:45+03:00" level=debug msg="dealer recv loop stopped" Jun 08 20:16:01 gnusmos go-librespot[1403]: time="2025-06-08T20:16:01+03:00" level=debug msg="obtained new client token: AADMSj9B5G+Kqaj8HIo3IP/VCnmD/0ObrdkoVz2ONGkLc3DN/D6NIQFDgV9Ykm1OK7wAD1DbiZiW0fISesVzTNe/i2N1yXKJKZ19ObVKW3iofbuB+KcoIIbFnQpuYvNHN9hUqKO5rrNJ2KbgdZLRb+U8opKE7Z6Guqh6SGW20pRycmHb2dnFx706hq5KlZ+xbSM5btoeYSUs+cbUgxEhNCshph/mP5hbgdwd2GCHgwuL1ZJ0GlWO1CTIAQ==" Jun 08 20:16:01 gnusmos go-librespot[1403]: time="2025-06-08T20:16:01+03:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="completed keyexchange" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="completed challenge" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=info msg="authenticated AP as kn511wtrxl4mf6avna0r9ydz0" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=info msg="authenticated Login5 as kn511wtrxl4mf6avna0r9ydz0" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=info msg="accepted zeroconf user kn511wtrxl4mf6avna0r9ydz0 from GOGO_MINI" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="dealer connection opened" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=trace msg="starting accesspoint recv loop" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=trace msg="starting dealer recv loop" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=trace msg="received accesspoint ping" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="received connection id: OWE4MTMwZjYtZjUyMi00YWQ2LWJjYWQtMmU0NmZhMTFkZmVlK2RlYWxlcit0Y3A6Ly8wYWNhNDFjMy5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArRkM3NkRBMDI4NkNFODRFNTBBNzYwMkNBODcxRTBCMDE4QUEzNTc0Q0VFRDY3Mzk4QjZDOTQxRjdBM0FCOUQxQg==" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=trace msg="received accesspoint pong ack" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="put connect state because NEW_DEVICE" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="handling transfer player command from da68c219a8619180a5f96ccd75801b8d86538cb5" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E8FY2kq5bkZpk" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E8FY2kq5bkZpk" Jun 08 20:16:02 gnusmos go-librespot[1403]: time="2025-06-08T20:16:02+03:00" level=debug msg="loading track (paused: false, position: 26815ms)" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=trace msg="emitting websocket event: will_play" Jun 08 20:16:03 gnusmos volumio[1203]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","play_origin":"playlist"}} Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="selected format OGG_VORBIS_320 (9833a51fa74a3271b2b39522341f4c3d303edfbe)" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="requested aes key for file 9833a51fa74a3271b2b39522341f4c3d303edfbe, gid: 3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1690" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1289" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="fetched first chunk of 20, total size is 10144784 bytes" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=trace msg="seek to 26815ms (diff: 81ms, samples: 1182541, bytes: 1313058)" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="created new output device" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=info msg="loaded track \"Five More Hours\" (paused: false, position: 26815ms, duration: 211975ms, prefetched: false)" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="fetched chunk 5/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=trace msg="scheduling prefetch in 155s" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=trace msg="emitting websocket event: metadata" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=trace msg="emitting websocket event: active" Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="sending successful reply for dealer request" Jun 08 20:16:03 gnusmos volumio[1203]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","name":"Five More Hours","artist_names":["Deorro","Chris Brown"],"album_name":"Good Evening","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02fe3951b474a76b0f25e3c760","position":26815,"duration":211975,"release_date":"year:2017 month:3 day:31","track_number":26,"disc_number":1}} Jun 08 20:16:03 gnusmos volumio[1203]: SPOTIFY: received: {"type":"active","data":null} Jun 08 20:16:03 gnusmos volumio[1203]: info: Aligning Spotify Volume to Volumio Volume Jun 08 20:16:03 gnusmos volumio[1203]: info: CoreCommandRouter::volumioGetState Jun 08 20:16:03 gnusmos volumio[1203]: info: Setting Spotify Volume from Volumio: 100 Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 08 20:16:03 gnusmos go-librespot[1403]: time="2025-06-08T20:16:03+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 08 20:16:04 gnusmos go-librespot[1403]: time="2025-06-08T20:16:04+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:16:04 gnusmos go-librespot[1403]: time="2025-06-08T20:16:04+03:00" level=trace msg="emitting websocket event: playing" Jun 08 20:16:04 gnusmos volumio[1203]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","play_origin":"playlist"}} Jun 08 20:16:04 gnusmos volumio[1203]: SPOTIFY: PUSH STATE SPOTIFY Jun 08 20:16:04 gnusmos volumio[1203]: SPOTIFY: {"status":"play","service":"spop","title":"Five More Hours","artist":"Deorro, Chris Brown","album":"Good Evening","albumart":"https://i.scdn.co/image/ab67616d00001e02fe3951b474a76b0f25e3c760","uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","trackType":"spotify","seek":26815,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 08 20:16:04 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:16:04 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:16:04 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:16:04 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:16:04 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:16:04 gnusmos volumio[1203]: SPOTIFY: PUSH STATE SPOTIFY Jun 08 20:16:04 gnusmos volumio[1203]: SPOTIFY: {"status":"play","service":"spop","title":"Five More Hours","artist":"Deorro, Chris Brown","album":"Good Evening","albumart":"https://i.scdn.co/image/ab67616d00001e02fe3951b474a76b0f25e3c760","uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","trackType":"spotify","seek":26815,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 08 20:16:04 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:16:04 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:16:04 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:16:04 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:16:05 gnusmos volumio[1203]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Jun 08 20:16:05 gnusmos volumio[1203]: info: Sending Spotify command with payload to local API: /player/volume Jun 08 20:16:05 gnusmos go-librespot[1403]: time="2025-06-08T20:16:05+03:00" level=debug msg="update volume to 65535/65535" Jun 08 20:16:06 gnusmos go-librespot[1403]: time="2025-06-08T20:16:06+03:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 08 20:16:06 gnusmos go-librespot[1403]: time="2025-06-08T20:16:06+03:00" level=trace msg="emitting websocket event: volume" Jun 08 20:16:06 gnusmos volumio[1203]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Jun 08 20:16:06 gnusmos volumio[1203]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Jun 08 20:16:08 gnusmos go-librespot[1403]: time="2025-06-08T20:16:08+03:00" level=debug msg="fetched chunk 6/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:19 gnusmos go-librespot[1403]: time="2025-06-08T20:16:19+03:00" level=debug msg="fetched chunk 7/19, size: 524288" uri="spotify:track:3MOECVkNshqHYTPt5DZcdN" Jun 08 20:16:25 gnusmos go-librespot[1403]: time="2025-06-08T20:16:25+03:00" level=debug msg="handling pause player command from da68c219a8619180a5f96ccd75801b8d86538cb5" Jun 08 20:16:25 gnusmos go-librespot[1403]: time="2025-06-08T20:16:25+03:00" level=debug msg="pause track at 48272ms" Jun 08 20:16:25 gnusmos go-librespot[1403]: time="2025-06-08T20:16:25+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:16:25 gnusmos go-librespot[1403]: time="2025-06-08T20:16:25+03:00" level=debug msg="sending successful reply for dealer request" Jun 08 20:16:25 gnusmos go-librespot[1403]: time="2025-06-08T20:16:25+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 08 20:16:25 gnusmos go-librespot[1403]: time="2025-06-08T20:16:25+03:00" level=trace msg="emitting websocket event: paused" Jun 08 20:16:25 gnusmos volumio[1203]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","play_origin":"playlist"}} Jun 08 20:16:25 gnusmos volumio[1203]: SPOTIFY: PUSH STATE SPOTIFY Jun 08 20:16:25 gnusmos volumio[1203]: SPOTIFY: {"status":"pause","service":"spop","title":"Five More Hours","artist":"Deorro, Chris Brown","album":"Good Evening","albumart":"https://i.scdn.co/image/ab67616d00001e02fe3951b474a76b0f25e3c760","uri":"spotify:track:3MOECVkNshqHYTPt5DZcdN","trackType":"spotify","seek":47815,"duration":211,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jun 08 20:16:25 gnusmos volumio[1203]: info: CoreCommandRouter::servicePushState Jun 08 20:16:25 gnusmos volumio[1203]: info: CoreStateMachine::pushState Jun 08 20:16:25 gnusmos volumio[1203]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 08 20:16:25 gnusmos volumio[1203]: info: CoreCommandRouter::volumioPushState Jun 08 20:16:25 gnusmos volumio[1203]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 08 20:16:30 gnusmos ntpd[990]: Soliciting pool server 2a05:f480:2c00:1d51:5400:5ff:fe04:6f3 Jun 08 20:16:32 gnusmos go-librespot[1403]: time="2025-06-08T20:16:32+03:00" level=trace msg="sent dealer ping" Jun 08 20:16:32 gnusmos go-librespot[1403]: time="2025-06-08T20:16:32+03:00" level=trace msg="received dealer pong" Jun 08 20:16:35 gnusmos volumio[1203]: info: [1749402995740] [80s80s] Pushing the next song state Sven Väth - Dein Schweiss and getting next track. Jun 08 20:16:35 gnusmos volumio[1203]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 08 20:16:35 gnusmos volumio[1203]: TypeError: Cannot set property 'name' of undefined Jun 08 20:16:35 gnusmos volumio[1203]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Jun 08 20:16:35 gnusmos volumio[1203]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Jun 08 20:16:35 gnusmos volumio[1203]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Jun 08 20:16:35 gnusmos volumio[1203]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Jun 08 20:16:35 gnusmos volumio[1203]: at processImmediate (internal/timers.js:461:21) Jun 08 20:16:35 gnusmos volumio[1203]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 08 20:16:35 gnusmos sudo[3491]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-08 20:15 Jun 08 20:16:35 gnusmos sudo[3491]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"