spotify playlist editing results in short outage on currently played song

bungh0l10 commented 1 year ago

Describe the bug

Editing playlist in spotify app (adding/removing a song from current queue) results in 1-2 second outage on the currently played track.

Preliminary Information

Firmware Version: SqueezeAmp 2.1634-16
Plugin Version: 0.501
Hardware Details

SqueezeAmp v3.20

NVS Settings


{
  "a2dp_ctmt": "1000",
  "a2dp_ctrld": "500",
  "a2dp_dev_name": "Squeezelite",
  "a2dp_sink_name": "SMSL BT4.2",
  "a2dp_spin": "0000",
  "actrls_config": "",
  "airplay_name": "ESP32-AirPlay-cedf24",
  "airplay_port": "5000",
  "ap_channel": "1",
  "ap_ip_address": "192.168.4.1",
  "ap_ip_gateway": "192.168.4.1",
  "ap_ip_netmask": "255.255.255.0",
  "ap_pwd": "squeezelite",
  "ap_ssid": "squeezelite-cedf24",
  "autoexec": "1",
  "autoexec1": "squeezelite -o I2S -b 500:2000 -d all=info -C 30 -W -n \"squeezelite-cedf24\"",
  "bat_config": "",
  "bt_name": "ESP32-BT-cedf24",
  "bt_sink_pin": "1234",
  "bt_sink_volume": "127",
  "bypass_wm": "0",
  "cspot_config": "{\"deviceName\":\"squeezelite-cedf24\",\"bitrate\":320,\"zeroConf\":1,\"volume\":21503}",
  "dac_config": "",
  "dac_controlset": "",
  "dhcp_tmout": "8",
  "display_config": "",
  "enable_airplay": "Y",
  "enable_bt_sink": "Y",
  "enable_cspot": "Y",
  "equalizer": "0,0,0,0,0,0,0,0,0,0",
  "eth_config": "",
  "ethtmout": "8",
  "gpio_exp_config": "",
  "host_name": "squeezelite-cedf24",
  "i2c_config": "",
  "jack_mutes_amp": "n",
  "led_brightness": "",
  "led_vu_config": "",
  "lms_ctrls_raw": "n",
  "loudness": "0",
  "metadata_config": "",
  "ota_erase_blk": "249856",
  "ota_prio": "6",
  "ota_stack": "10240",
  "pollmin": "15",
  "pollmx": "600",
  "rel_api": "https://api.github.com/repos/sle118/squeezelite-esp32/releases",
  "release_url": "https://github.com/sle118/squeezelite-esp32/releases",
  "rotary_config": "",
  "set_GPIO": "0=ir",
  "sleep_config": "",
  "spdif_config": "",
  "spi_config": "",
  "stats": "N",
  "target": "",
  "telnet_block": "500",
  "telnet_buffer": "40000",
  "telnet_enable": "Y"
}

Logs


=== START OF LOG ===
[00:42:00.612] I MercurySession.cpp:42: Received packet, command: 181
[00:42:00.619] D SpircHandler.cpp:69: Received subscription response
[00:42:00.627] D SpircHandler.cpp:179: Load frame 1!
[00:42:00.632] D MercurySession.cpp:252: Executing Mercury Request, type SEND
[0042[:00:0042:.647] I TrackPlayer.cpp:98: Resetting state
00.648] D MercurySession.cpp:252: Executing Mercury Request, type GET
[00:42:00.662] I TrackPlayer.cpp:254: Playing done
[00:42:00.714] I MercurySession.cpp:42: Received packet, command: 178
[00:42:00.718] D MercurySession.cpp:174: Received mercury packet
[00:42:00.724] I TrackQueue.cpp:158: Track name: Mortal Kombat 2
[00:42:00.729] I TrackQueue.cpp:159: Track duration: 198240
[00:42:00.730] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1
[00:42:00.732] D TrackQueue.cpp:212: File format: 2
[00:42:00.769] I MercurySession.cpp:42: Received packet, command: 178
[00:42:00.771] D MercurySession.cpp:174: Received mercury packet
[00:42:00.886] I MercurySession.cpp:42: Received packet, command: 13
[00:42:00.888] I TrackQueue.cpp:252: Got audio key
[00:42:00.893] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[00:42:01.662] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/1c8983ef5af16e327caa78ae50e51a04cd9b990e?__token__=exp=1698674819~hmac=4f4f912f6bda9cd9faa18f8c3f4e944ab492fe99e94114c980e53a42f28bc4de
[00:42:01.664] I TrackPlayer.cpp:171: Got track ID=1c8983ef5af16e327caa78ae50e51a04cd9b990e
[00:42:01.668] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/1c8983ef5af16e327caa78ae50e51a04cd9b990e?__token__=exp=1698674819~hmac=4f4f912f6bda9cd9faa18f8c3f4e944ab492fe99e94114c980e53a42f28bc4de
[00:42:03.141] I CDNAudioFile.cpp:70: Header and footer bytes received
[00:42:03.145] D MercurySession.cpp:252: Executing Mercury Request, type SEND
[00:42:03.150] D MercurySession.cpp:252: Executing Mercury Request, type SEND
[00:42:03.157] cspot_cmd_handler:381 CSpot start track
[00:42:03.158] I Shim.cpp:217: (re)start playing at 0
[00:42:03.160] cspot_cmd_handler:394 CSpot play
[00:42:03.257] I MercurySession.cpp:42: Received packet, command: 178
[00:42:03.260] D MercurySession.cpp:174: Received mercury packet
[00:42:03.413] I MercurySession.cpp:42: Received packet, command: 178
[00:42:03.416] D MercurySession.cpp:174: Received mercury packet
[00:42:03.499] I TrackPlayer.cpp:205: Playing
[00:42:03.550] I Shim.cpp:120: new track started <> => <1c8983ef5af16e327caa78ae50e51a04cd9b990e>
[00:42:03.553] I Shim.cpp:262: next track will play in 0 ms
[00:42:03.582] _output_frames:150 track start sample rate: 44100 replay_gain: 0
[00:42:03.618] I Shim.cpp:416: next track's audio has reached DAC (offset 0)
[00:42:03.622] D MercurySession.cpp:252: Executing Mercury Request, type SEND
[00:42:03.637] D MercurySession.cpp:252: Executing Mercury Request, type SEND
[00:42:03.767] I MercurySession.cpp:42: Received packet, command: 178
[00:42:03.769] D MercurySession.cpp:174: Received mercury packet
[00:42:03.920] I MercurySession.cpp:42: Received packet, command: 178
[00:42:03.923] D MercurySession.cpp:174: Received mercury packet
[00:42:42.363] I MercurySession.cpp:42: Received packet, command: 4
[00:42:42.366] D TimeProvider.cpp:15: Time synced with spotify servers
[00:42:42.405] I MercurySession.cpp:42: Received packet, command: 74
[00:43:11.788] I MercurySession.cpp:42: Received packet, command: 181
[00:43:11.792] D SpircHandler.cpp:69: Received subscription response
[00:43:11.797] D SpircHandler.cpp:204: Got replace frame
[00:43:11.803] D MercurySession.cpp:252: Executing Mercury Request, type SEND
[00:43:11.819] cspot_cmd_handler:405 CSpot flush
[00:43:11.819] I TrackPlayer.cpp:98: Resetting state
[00:43:11.835] D MercurySession.cpp:252: Executing Mercury Request, type GET
[00:43:11.860] I TrackPlayer.cpp:254: Playing done
[00:43:11.890] I MercurySession.cpp:42: Received packet, command: 178
[00:43:11.892] D MercurySession.cpp:174: Received mercury packet
[00:43:11.896] I TrackQueue.cpp:158: Track name: Mortal Kombat 2
[00:43:11.897] I TrackQueue.cpp:159: Track duration: 198240
[00:43:11.898] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1
[00:43:11.900] D TrackQueue.cpp:212: File format: 2
[00:43:11.971] I MercurySession.cpp:42: Received packet, command: 178
[00:43:11.973] D MercurySession.cpp:174: Received mercury packet
[00:43:12.146] I MercurySession.cpp:42: Received packet, command: 13
[00:43:12.148] I TrackQueue.cpp:252: Got audio key
[00:43:12.150] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[00:43:12.814] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/1c8983ef5af16e327caa78ae50e51a04cd9b990e?__token__=exp=1698674891~hmac=8d7ab3eb7a132bfd3d8b88ef1e1d7e00c3cb1b58ea1f04c27429ee1c99b5cb87
[00:43:12.816] I TrackPlayer.cpp:171: Got track ID=1c8983ef5af16e327caa78ae50e51a04cd9b990e
[00:43:12.819] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/1c8983ef5af16e327caa78ae50e51a04cd9b990e?__token__=exp=1698674891~hmac=8d7ab3eb7a132bfd3d8b88ef1e1d7e00c3cb1b58ea1f04c27429ee1c99b5cb87
[00:43:12.836] output_thread_i2s:518 Output state is -1
[00:43:12.837] output_thread_i2s:522 switching off amp GPIO -1
[00:43:12.923] D MercurySession.cpp:252: Executing Mercury Request, type GET
[00:43:13.018] I MercurySession.cpp:42: Received packet, command: 178
[00:43:13.020] D MercurySession.cpp:174: Received mercury packet
[00:43:13.024] I TrackQueue.cpp:158: Track name: I’m The President
[00:43:13.025] I TrackQueue.cpp:159: Track duration: 247000
[00:43:13.027] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1
[00:43:13.029] D TrackQueue.cpp:212: File format: 2
[00:43:13.157] I MercurySession.cpp:42: Received packet, command: 13
[00:43:13.159] I TrackQueue.cpp:252: Got audio key
[00:43:13.167] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[00:43:14.268] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/9c8ccabb2804dde06e0515e0569c61bc4b6635fd?__token__=exp=1698674892~hmac=aa44c3d64ce0d58aff76cc07ee1edc6b70e37370bc5ca4cad3ccc84081098958
[00:43:14.443] I CDNAudioFile.cpp:70: Header and footer bytes received
[00:43:14.446] D MercurySession.cpp:252: Executing Mercury Request, type SEND
[00:43:14.457] D MercurySession.cpp:252: Executing Mercury Request, type SEND
[00:43:14.466] cspot_cmd_handler:381 CSpot start track
[00:43:14.467] I Shim.cpp:217: (re)start playing at 68968
[00:43:14.468] cspot_cmd_handler:394 CSpot play
[00:43:14.532] output_thread_i2s:518 Output state is 2
[00:43:14.534] output_thread_i2s:585 Restarting I2S.
[00:43:14.556] I MercurySession.cpp:42: Received packet, command: 178
[00:43:14.559] D MercurySession.cpp:174: Received mercury packet
[00:43:14.654] I MercurySession.cpp:42: Received packet, command: 178
[00:43:14.659] D MercurySession.cpp:174: Received mercury packet
[00:43:15.707] I TrackPlayer.cpp:205: Playing
[00:43:15.709] I Shim.cpp:120: new track started <> => <1c8983ef5af16e327caa78ae50e51a04cd9b990e>
[00:43:15.710] I Shim.cpp:262: next track will play in 0 ms
[00:43:15.741] _output_frames:150 track start sample rate: 44100 replay_gain: 0
[00:43:15.869] I Shim.cpp:416: next track's audio has reached DAC (offset 68968)
[00:43:15.879] D MercurySession.cpp:252: Executing Mercury Request, type SEND
[00:43:15.994] I MercurySession.cpp:42: Received packet, command: 178
[00:43:15.999] D MercurySession.cpp:174: Received mercury packet
=== END OF LOG ===

Issue Description

Observed Behavior: Shortly after adding another song to the current queue using Spotify app, the currently played song gets muted for about 1-2 seconds.
Expected Behavior: The currently played song should play without interruption.
Steps to Reproduce: open spotify app, connect to squeezeamp, play a song, add whatever song to the current queue, now you should expeience an outage of 1-2 seconds , song continues. If you now remove this previously added song from the queue the currently played song will again encounter a short outage.

sle118 commented 1 year ago

This is possibly more an issue with cspot, but I'll let @philippe44 and @feelfreelinux to chime in.

philippe44 commented 1 year ago

Yes, it is by design - the current track must be reloaded

philippe44 commented 1 year ago

I had an idea and submitted a PR to @feelfreelinux but it's a touchy topic and I know he is busy currently so I don't know he will agree or even have time to review it.

philippe44 commented 1 year ago

You can try the latest artifacts

bungh0l10 commented 1 year ago

WOW! Thanks for the swift replies! Currently checking latest build and my first observations look very promising. No gaps thus far while editing the current playlist on the fly. I wasn't able to test Spotify Jam with others yet though, neighther remote nor within the same wifi. This might take a while to report back.

sle118 commented 1 year ago

Ok going to close for now. Reopen it if needed

bungh0l10 commented 1 year ago

Hey guys,

I'm very sorry for the late reply. I just wanted to give you a response on my outstanding feedback.

I tried multiple variants adding songs to queue while being in jams, locally, and remote as well. None of those sessions produced gaps anymore while me or others were adding songs to the queue :) Thank you so much, that is awesome!!!

I encountered one thing while testing. I actually do not know if I should report it here (new issue) or with cspot. Please guide me to the correct direction for this report. ;)

Steps to reproduce:

1.) Connect to Squeezeamp (or different capable ESP32) via Spotify app. 2.) Start a playlist (for example, "release radar" from Spotify. I was able to reproduce with other playlists as well.) 3.) After the first song has finished and the second song starts playing, add 4 random songs to the queue. 4.) After those 4 songs have finished, let the following song from the initial playlist play and add another random song to the queue. 5.) The now queued song will not be played afterwards, but is skipped instead. You can add +x songs to the queue afterwards, but none of them will be played anymore and the initial playlist will keep playing. The only way to "reset" this behavior is to clear the current queue by overriding it with a single song or another playlist.

I know this takes some time to reproduce, but I wanted to provide a reliable way to reproduce instead of a wonky description.

The reason I'm providing this here is because 1634 (the version before the patch) behaved differently (not better) and I just wanted to highlight it with you guys as you might be able to recognize what changed and puzzle bits and pieces together for good. You can follow on 1634 with the previously provided steps but step 5 behaves as follows..

5.) The now queued song will not be played afterwards but is skipped instead. You can try to add songs to the queue afterwards, but after adding the first song to the queue, it will be started straight away instead of being added to the queue. Unfortunately all further added songs will be ignored/skipped as well .

Thanks again for developing this stellar project! :)

bungh0l10 commented 1 year ago

Hello again,

I've had some time to do some more testing today and I just wanted to highlight my findings with you as @philippe44 mentioned it might be a touchy topic where I think (assume) he is onto something here. It is not about the gap, this seems to be solved (thanks again). I'm just trying to express onto different behaviours before/after the patch.

I'm just writing steps to reproduce as I was able to reproduce this having two SqueezeAmps and another ESP32 device as well, ecountering the same behaviours and hope you can reproduce on your end as well (If not please tell me and I'll add logs or file it with cspot instead).

-> 1634 (before patch) 1.) Connect to Squeezeamp (or different capable ESP32) via Spotify app. 2.) Start a playlist or an album (for example, "release radar" from Spotify. I was able to reproduce with other playlists as well.) 3.) During the First song add 1 more random song to the queue. 4.) After this 1 song has finished, let the queued song play as well as the following from the initial playlist and add another random song to the queue. 5.) The now queued song will be played immideatly instead of being queued (Spotify app will still display the previous played song with progress bar progressing) 6.) You can add another song now to queue which get s started instant again (It seems to start with the exact seconds progresed already as the currently played song .

-> 1650 1.) Connect to Squeezeamp (or different capable ESP32) via Spotify app. 2.) Start a playlist or an album (for example, "release radar" from Spotify. I was able to reproduce with other playlists as well.) 3.) During the First song add 1 more random song to the queue. 4.) After this 1 song has finished, let the queued song play as well as the following from the initial playlist and add another random song to the queue. 5.) The now queued song will be queued but skipped and not played. You can add more songs to queue but none of them will be played anymore.

Sorry but I haven't found an option to reopen.

Thanks again :)

philippe44 commented 1 year ago

I've pushed an update but I'm really not sure as I'm touching some cspot delicate pieces

bungh0l10 commented 1 year ago

I'm currently traveling. I'll check latest artifact and try to update you by the end of the week. Thanks a bunch!

bungh0l10 commented 1 year ago

Hi @philippe44 ,

Having a jam going on for 5+ hours now, we encountered literally little to complain about.

no gaps
adding songs doesn't interfere
interchanging queued songs doesnt't interefer
forwarding (skip) songs (max 2) works
multiple times adding songs works
pausing and resuming songs works
Spotify app stays in sync with what you currently hear

but (these might be physical issues related to ESP32 - not software related) just to mention it:

if you add songs to the queue very, very, very fast, it will skip / overwrite the previously queued song (you can watch it live while having the queue next to you)
queuing a song at the very very very end (<1s) of the currently played song could cause the the currently played song to repeat

pros after latest patch

none of your changes caused any trouble, misbehavior or disadvantage in any way!

all previous mentions have been adressed
you can skip forward (IF) you ecounter misbehaviours and still add songs, and the queue will move along.

THIS IS GREAT! Thanks so much! It almost feels like controlling native clients like eg. Denon/Marantz receivers with only limitation not being able to skip back to previously queued songs. But this honestly is complaining on a high level.

It works like a charm and squeezeamp is a top notch party device!

Personally I'd say issue can be closed.

These changes might be also beneficial to get merged to the C-spot repo.

Thank you!

philippe44 commented 1 year ago

@bungh0l10 thanks for testing, highly appreciated. I've backported that to cspot indeed and the maintainer has accepted it.

sle118 / squeezelite-esp32