Loops stop working after stopping or playing audio over another

[AlejandroCabeza]

Songbird version: 0.4.1

Rust version (rustc -V): rustc 1.75.0 (82e1608df 2023-12-21)

Serenity version: 0.12.1

Output of ffmpeg -version, yt-dlp --version (if relevant):
Not using either of those, but just in case:

• ffmpeg version 6.0

Description:
Loops stop working after running stop or playing another audio when one is already being played.
This happens both for LoopState.Infinite, as well as LoopState.Finite(x) for x > 0.

Steps to reproduce:

1. Instantiate two tracks with LoopState.Infinite. They can be the same file.
2. Play one of them.
3. While the previous track is playing, play the other one.
4. The currently playing track while get overridden by the new one, but the new one will behave as LoopState.Finite(0), not as expected with LoopState.Infinite.
5. From now on, LoopState.Infinite doesn't work anymore. All tracks played after this will behave as if LoopState.Finite(0).

Additional Information
There are many other combinations that come to my mind, but I haven't tried them all. Let me know if I can help debugging this in any way.

[FelixMcFelix]

It sounds as though there may be an ordering mismatch between tracks in the event context and the audio task itself. I don't know when I'll have the time to dig into this, but if you add an event listener (state change, loop, etc.) you should be able to see what the Event side of the house believes your track state is. You can compare this with the output from TrackHandle::get_info to see who's wrong.

[AlejandroCabeza]

It sounds as though there may be an ordering mismatch between tracks in the event context and the audio task itself. I don't know when I'll have the time to dig into this, but if you add an event listener (state change, loop, etc.) you should be able to see what the Event side of the house believes your track state is. You can compare this with the output from TrackHandle::get_info to see who's wrong.

Thanks for the answer. I'll give it a try in the weekend :)

[ofiddy]

I've had this problem too. I tried having a look at it myself but I'm definitely too green with Rust to figure out what was going on. Only the first song played would loop: any others would not.

[JellyWX]

I'm figuring that I'll have to update Songbird at some point for Discord's crypto so I'm having a look into this as it's pretty breaking for me. Here's a debug log for the actions

• Join
• Play non-looping audio
• Stop
• Play looping audio (and break)

[2024-12-03T18:46:21Z DEBUG songbird::manager] Initialising Songbird for Serenity: ID UserId(InnerId(603277495407607808)), 1 Shards
[2024-12-03T18:46:21Z DEBUG songbird::manager] Songbird (UserId(InnerId(603277495407607808))) Initialised!
[2024-12-03T18:46:21Z DEBUG songbird::manager] Registering Serenity shard handle 0 with Songbird
[2024-12-03T18:46:21Z DEBUG songbird::shards] Adding shard handle send channel...
[2024-12-03T18:46:21Z DEBUG songbird::shards] Added shard handle send channel.
[2024-12-03T18:46:21Z DEBUG songbird::shards] Clearing queued messages...
[2024-12-03T18:46:21Z DEBUG songbird::shards] Cleared queued messages.
[2024-12-03T18:46:21Z DEBUG songbird::manager] Registered shard handle 0.
[2024-12-03T18:46:31Z INFO  songbird::handler] from_config; guild_id=GuildId(355102571561484289) ws=Serenity(SerenityShardHandle { sender: RwLock { data: Some(UnboundedSender { closed: false }) }, queue: Mutex { data: [] } }) user_id=UserId(603277495407607808) config=Config { crypto_mode: Aes256Gcm, gateway_timeout: Some(10s), mix_mode: Stereo, preallocated_tracks: 1, driver_retry: Retry { strategy: Backoff(ExponentialBackoff { min: 250ms, max: 10s, jitter: 0.1 }), retry_limit: Some(5) }, use_softclip: true, driver_timeout: Some(10s), disposer: Some(DisposalThread(Sender)), scheduler: None }
[2024-12-03T18:46:31Z INFO  songbird::handler] join; channel_id=ChannelId(711362068162412604)
[2024-12-03T18:46:31Z INFO  songbird::driver::tasks] runner; config=Config { crypto_mode: Aes256Gcm, gateway_timeout: Some(10s), mix_mode: Stereo, preallocated_tracks: 1, driver_retry: Retry { strategy: Backoff(ExponentialBackoff { min: 250ms, max: 10s, jitter: 0.1 }), retry_limit: Some(5) }, use_softclip: true, driver_timeout: Some(10s), disposer: Some(DisposalThread(Sender)), scheduler: None }
[2024-12-03T18:46:31Z INFO  songbird::handler] update_state; session_id="xxx" channel_id=Some(ChannelId(InnerId(711362068162412604)))
[2024-12-03T18:46:31Z INFO  songbird::handler] update_server; endpoint="rotterdam11007.discord.media:443"
[2024-12-03T18:46:31Z INFO  songbird::driver] raw_connect; info=ConnectionInfo { channel_id: Some(ChannelId(711362068162412604)), endpoint: "rotterdam11007.discord.media:443", guild_id: GuildId(355102571561484289), session_id: "xxx", token: "<secret>", user_id: UserId(603277495407607808) } tx=Sender
[2024-12-03T18:46:31Z INFO  songbird::ws] connect; url=Url { scheme: "wss", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("rotterdam11007.discord.media")), port: None, path: "/", query: Some("v=4"), fragment: None }
[2024-12-03T18:46:31Z INFO  songbird::driver::connection] Crypto scheme negotiation -- wanted Aes256Gcm. Chose Aes256Gcm from modes ["aead_aes256_gcm_rtpsize", "aead_aes256_gcm", "aead_xchacha20_poly1305_rtpsize", "xsalsa20_poly1305_lite_rtpsize", "xsalsa20_poly1305_lite", "xsalsa20_poly1305_suffix", "xsalsa20_poly1305"].
[2024-12-03T18:46:31Z DEBUG songbird::ws] Unexpected JSON: invalid value: integer `11`, expected opcode in [0--9] + [12--13] at line 1 column 8. Payload: {"op":11,"d":{"user_ids":["203532103185465344"]}}
[2024-12-03T18:46:31Z DEBUG songbird::ws] Unexpected JSON: invalid value: integer `18`, expected opcode in [0--9] + [12--13] at line 1 column 8. Payload: {"op":18,"d":{"user_id":"203532103185465344","flags":2}}
[2024-12-03T18:46:31Z DEBUG songbird::ws] Unexpected JSON: invalid value: integer `20`, expected opcode in [0--9] + [12--13] at line 1 column 8. Payload: {"op":20,"d":{"user_id":"203532103185465344","platform":0}}
[2024-12-03T18:46:32Z INFO  songbird::driver::connection] Connected to: rotterdam11007.discord.media:443
[2024-12-03T18:46:32Z INFO  songbird::driver::connection] WS heartbeat duration 13750ms.
[2024-12-03T18:46:32Z INFO  songbird::driver::tasks::ws] run; interconnect=Interconnect { core: Sender, events: Sender, mixer: Sender }
[2024-12-03T18:46:32Z INFO  songbird::handler] deafen; deaf=true
[2024-12-03T18:46:32Z INFO  songbird::driver::tasks::events] Event state for track 1 added
[2024-12-03T18:46:32Z INFO  songbird::driver::tasks::ws] Changing to SpeakingState(MICROPHONE)
[2024-12-03T18:46:32Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Ready(Preparing)
[2024-12-03T18:46:32Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Volume(1.0)
[2024-12-03T18:46:32Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Loops(Finite(0), true)
[2024-12-03T18:46:32Z INFO  songbird::events::store] Firing Preparing for [0]
[2024-12-03T18:46:32Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Ready(Playable)
[2024-12-03T18:46:32Z INFO  songbird::events::store] Firing Playable for [0]
[2024-12-03T18:46:32Z INFO  songbird::handler] update_state; session_id="xxx" channel_id=Some(ChannelId(InnerId(711362068162412604)))
[2024-12-03T18:46:33Z INFO  songbird::driver::tasks::events] Event state for all tracks removed.
[2024-12-03T18:46:33Z INFO  songbird::driver::tasks::ws] Changing to SpeakingState(0x0)
[2024-12-03T18:46:40Z INFO  songbird::handler] deafen; deaf=true
[2024-12-03T18:46:40Z INFO  songbird::driver::tasks::events] Event state for track 1 added
[2024-12-03T18:46:40Z INFO  songbird::driver::tasks::ws] Changing to SpeakingState(MICROPHONE)
[2024-12-03T18:46:40Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Ready(Preparing)
[2024-12-03T18:46:40Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Volume(1.0)
[2024-12-03T18:46:40Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Loops(Infinite, true)
[2024-12-03T18:46:40Z INFO  songbird::events::store] Firing Preparing for [0]
[2024-12-03T18:46:40Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Ready(Playable)
[2024-12-03T18:46:40Z INFO  songbird::events::store] Firing Playable for [0]
[2024-12-03T18:46:40Z INFO  songbird::handler] update_state; session_id="xxx" channel_id=Some(ChannelId(InnerId(711362068162412604)))
[2024-12-03T18:46:42Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Loops(Infinite, false)
[2024-12-03T18:46:42Z INFO  songbird::events::store] Firing Loop for [0]
[2024-12-03T18:46:42Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Loops(Infinite, false)
[2024-12-03T18:46:42Z INFO  songbird::events::store] Firing Loop for [0]
[2024-12-03T18:46:42Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Loops(Infinite, false)
[2024-12-03T18:46:42Z INFO  songbird::events::store] Firing Loop for [0]
[2024-12-03T18:46:42Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Loops(Infinite, false)
[2024-12-03T18:46:42Z INFO  songbird::events::store] Firing Loop for [0]
[2024-12-03T18:46:42Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Loops(Infinite, false)
[2024-12-03T18:46:42Z INFO  songbird::events::store] Firing Loop for [0]
...

The "Firing Loop for [0]" repeats endlessly (multiple times per second) but no audio is played- something is getting stuck in a loop somewhere

For comparison, when working (i.e, no play/stop/play sequence), the debug log is like so:

[2024-12-03T18:52:05Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Loops(Infinite, false)
[2024-12-03T18:52:05Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Ready(Preparing)
[2024-12-03T18:52:05Z INFO  songbird::events::store] Firing Preparing for [0]
[2024-12-03T18:52:05Z INFO  songbird::events::store] Firing Loop for [0]
[2024-12-03T18:52:05Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Position(0ns)
[2024-12-03T18:52:05Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Ready(Playable)
[2024-12-03T18:52:05Z INFO  songbird::events::store] Firing Playable for [0]
[2024-12-03T18:52:07Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Loops(Infinite, false)
[2024-12-03T18:52:07Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Ready(Preparing)
[2024-12-03T18:52:07Z INFO  songbird::events::store] Firing Preparing for [0]
[2024-12-03T18:52:07Z INFO  songbird::events::store] Firing Loop for [0]
[2024-12-03T18:52:07Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Position(0ns)
[2024-12-03T18:52:07Z DEBUG songbird::driver::tasks::events] Changing state for track 0 of 1: Ready(Playable)
[2024-12-03T18:52:07Z INFO  songbird::events::store] Firing Playable for [0]

(Audio is a 2s loop so the event order here is correct)

[JellyWX]

This has fixed it for me

jude@pop-os:~/songbird$ git diff
diff --git a/src/driver/tasks/mixer/mod.rs b/src/driver/tasks/mixer/mod.rs
index 1c825c6d..e80ea3c1 100644
--- a/src/driver/tasks/mixer/mod.rs
+++ b/src/driver/tasks/mixer/mod.rs
@@ -231,6 +231,7 @@ impl Mixer {
             MixerMessage::AddTrack(t) => self.add_track(t),
             MixerMessage::SetTrack(t) => {
                 self.tracks.clear();
+                self.track_handles.clear();
 
                 let mut out = self.fire_event(EventMessage::RemoveAllTracks);
 

Not done any sort of thorough testing. I've spent a while looking at the code without picking up much understanding, so wanted to ask if this looks like a reasonable oversight/issue (in which case I'll MR), or if this is going to cause further issues.

My theory is that not clearing track_handles causes the loop in mix_tracks to attempt to perform seek on an orphaned track_handle in the looping logic, as it uses the index of the track (tracks.len eq 1), and not the index of the track_handle (track_handles.len eq 2)