I catched the plugin stop:
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="created new output device"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=info msg="loaded track \"What Lovers Do (feat. SZA)\" (paused: true, position: 0ms, duration: 199849ms, prefetched: false)" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: metadata"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: stopped"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: stopped"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: paused"
After that no sound, but tracks changing, no time counts
follow the full log, till was pressed “Play next track”, then you will see fetched chunks and music becomes playing.
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="cleared closed output device"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="created new output device"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=info msg="loaded track \"What Lovers Do (feat. SZA)\" (paused: true, position: 0ms, duration: 199849ms, prefetched: false)" uri="spotify:track:0GxQ1A5L9xnMOytbP6eKBG"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: metadata"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: stopped"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: stopped"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":"go-librespot"}}
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:48:58 living go-librespot[1056]: time="2024-10-12T19:48:58+03:00" level=trace msg="emitting websocket event: paused"
Oct 12 19:48:58 living volumio[851]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0GxQ1A5L9xnMOytbP6eKBG","play_origin":"go-librespot"}}
Oct 12 19:52:40 living go-librespot[1056]: time="2024-10-12T19:52:40+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:56:17 living go-librespot[1056]: time="2024-10-12T19:56:17+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="resolved context of track" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="emitting websocket event: will_play"
Oct 12 19:59:58 living volumio[851]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5MqFJxMwbZ5nyNogTDVTeL","play_origin":"go-librespot"}}
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="selected format OGG_VORBIS_320 (2aeb773fcb588ce3bc7b262ac72607b53b2c47b6)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="requested aes key for file 2aeb773fcb588ce3bc7b262ac72607b53b2c47b6, gid: 5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1730"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="fetched first chunk of 18, total size is 9222612 bytes" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=info msg="loaded track \"(I Just) Died In Your Arms (Original Radio Edit)\" (paused: false, position: 0ms, duration: 215109ms, prefetched: false)" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="scheduling prefetch in 185s"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="emitting websocket event: metadata"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=trace msg="emitting websocket event: playing"
Oct 12 19:59:58 living volumio[851]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5MqFJxMwbZ5nyNogTDVTeL","play_origin":"go-librespot"}}
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1726"
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Oct 12 19:59:58 living go-librespot[1056]: time="2024-10-12T19:59:58+03:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 19:59:59 living go-librespot[1056]: time="2024-10-12T19:59:59+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1324"
Oct 12 19:59:59 living go-librespot[1056]: time="2024-10-12T19:59:59+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Oct 12 20:00:10 living go-librespot[1056]: time="2024-10-12T20:00:10+03:00" level=debug msg="fetched chunk 4/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"
Oct 12 20:00:22 living go-librespot[1056]: time="2024-10-12T20:00:22+03:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:5MqFJxMwbZ5nyNogTDVTeL"