search

serenity-rs / songbird

An async Rust library for the Discord voice API
ISC License
384 stars 110 forks source link

Seeking advisory: Unexpected end of stream. #188

Closed Skarlett closed 1 year ago

Skarlett commented 1 year ago

Songbird version: 0.3.2

Rust version (rustc -V):1.69

Serenity/Twilight version: 0.11

Description: https://github.com/Skarlett/coggie-bot/blob/7e36f7accd124a5286f191be8c42b7fda939ca48/crates/mockingbird/src/deemix.rs After producing my own Restartable based off of ytdl, I've been occasionally (~2h intervals) experiencing partial playtime with unexpectedly endings to song. For example, a song may play for 1 minute, while its duration is 3 minutes.

Digging through the logs, yields the following.

Some other circumstances to know of is that the process creating the mp3 stream is slightly CPU aggressive due to it decrypting the stream on the fly.

I do not believe this to attributed to your library, but If you have a few moments to look over the following and give advice would be appreciated greatly.

Edit: Deprecated logs.

May 30 09:46:06 HOSTNAME start[410738]: 2023-05-30T13:46:06.949534Z  WARN serenity::model::channel: Unknown ChannelType value: 15
May 30 15:44:40 HOSTNAME start[410738]: 2023-05-30T19:44:40.949734Z  WARN serenity::gateway::shard: [Shard [0, 1]] Unknown unclean close 1001: Some("")
May 30 16:56:53 HOSTNAME start[410738]: 2023-05-30T20:56:53.527321Z  WARN serenity::gateway::shard: [Shard [0, 1]] Websocket error: Protocol(ResetWithoutClosingHandshake)
May 30 17:41:53 HOSTNAME start[410738]: 2023-05-30T21:41:53.288305Z  WARN serenity::gateway::shard: [Shard [0, 1]] Websocket error: Protocol(ResetWithoutClosingHandshake)
May 30 19:32:27 HOSTNAME start[410738]: 2023-05-30T23:32:27.595678Z  WARN serenity::gateway::shard: [Shard [0, 1]] Websocket error: Protocol(ResetWithoutClosingHandshake)

While experimenting, I was able to isolate a log from songbird. the Logs presented above seem to have no relation as they're not spawned on the event.

New Logs

May 31 04:19:44 HOSTNAME start[421206]: 2023-05-31T08:19:44.536558Z  INFO runner: songbird::tracks::queue: Queued track ended: Track([(TrackState { playing: End, volume: 1.0, position: 72.94s, play_time: 72.94s, loops: Finite(0) }, TrackHandle { inner: InnerHandle { command_channel: Sender, seekable: false, uuid: 70e1b446-e634-4aff-a0b9-ba8a5b16e4f3, metadata: Metadata { track: Some("HereWeGoAgain"), artist: Some("Kid Andre"), date: None, channels: Some(2), channel: None, start_time: None, duration: Some(194s), sample_rate: Some(48000), source_url: None, title: None, thumbnail: None }, typemap: "<LOCK>" } })]).
May 31 04:26:11 HOSTNAME start[421206]: 2023-05-31T08:26:11.297794Z  INFO runner: songbird::tracks::queue: Queued track ended: Track([(TrackState { playing: End, volume: 1.0, position: 59.28s, play_time: 59.28s, loops: Finite(0) }, TrackHandle { inner: InnerHandle { command_channel: Sender, seekable: false, uuid: 1b11e710-ef46-409b-bbb9-6bd85cde4b76, metadata: Metadata { track: Some("Bad Friends"), artist: Some("Kofi"), date: None, channels: Some(2), channel: None, start_time: None, duration: Some(161s), sample_rate: Some(48000), source_url: None, title: None, thumbnail: None }, typemap: "<LOCK>" } })]).

Transaction between two songs + known bug

2432077712863295)), endpoint: "us-central6509.discord.media:443", guild_id: GuildId(942432077079535656), session_id: "3712b981d4a0fd00e00386823f1e4a72", token: "<secret>", user_id: UserId(461359650496053258) }}:run{interconnect=Interconnect { core: Sender, events: Sender, mixer: Sender }}: songbird::driver::tasks::ws: Changing to (empty)
May 31 05:53:17 start[421206]: 2023-05-31T09:53:17.413156Z  INFO dispatch:max_pipe_size: mockingbird::deemix: max pipe size: 1048576
May 31 05:53:17 start[421206]: 2023-05-31T09:53:17.413265Z  INFO dispatch: mockingbird::deemix: Running: deemix-stream  https://open.spotify.com/track/3e33dvuv9f0nmotCXMJmL2?si=17abc74a74334f15
May 31 05:53:27 start[421206]: 2023-05-31T09:53:27.634342Z  INFO dispatch: mockingbird::deemix: running ffmpeg
May 31 05:53:27 start[421206]: 2023-05-31T09:53:27.638617Z  INFO dispatch: mockingbird::deemix: deezer metadata Some(Metadata { track: Some("BedfordFalls"), artist: Some("Bones"), date: None, channels: Some(2), channel: None, start_time: None, duration: Some(174s), sample_rate: Some(48000), source_url: None, title: None, thumbnail: None })
May 31 05:53:27 start[421206]: 2023-05-31T09:53:27.773072Z  INFO dispatch: mockingbird::deemix: load time: 0.134241171
May 31 05:53:27 start[421206]: 2023-05-31T09:53:27.773479Z  INFO dispatch: songbird::tracks::queue: Track added to queue.
May 31 05:53:27 start[421206]: 2023-05-31T09:53:27.795709Z  INFO runner: songbird::driver::tasks::events: Event state for track 1 added
May 31 05:53:27 start[421206]: 2023-05-31T09:53:27.795793Z  INFO runner{evt_rx=Receiver ssrc=751826 heartbeat_interval=13750.0 attempt_idx=1 info=ConnectionInfo { channel_id: Some(ChannelId(942432077712863295)), endpoint: "us-central6509.discord.media:443", guild_id: GuildId(942432077079535656), session_id: "3712b981d4a0fd00e00386823f1e4a72", token: "<secret>", user_id: UserId(461359650496053258) }}:run{interconnect=Interconnect { core: Sender, events: Sender, mixer: Sender }}: songbird::driver::tasks::ws: Changing to MICROPHONE
May 31 05:53:56 start[421206]: 2023-05-31T09:53:56.187455Z  INFO dispatch:max_pipe_size: mockingbird::deemix: max pipe size: 1048576
May 31 05:53:56 start[421206]: 2023-05-31T09:53:56.187625Z  INFO dispatch: mockingbird::deemix: Running: deemix-stream  https://open.spotify.com/track/1ZNVczQsUBA64aWhvWqaap?si=23aaa11a31b9456b
May 31 05:54:10 start[421206]: 2023-05-31T09:54:10.647099Z  INFO dispatch: mockingbird::deemix: running ffmpeg
May 31 05:54:10 start[421206]: 2023-05-31T09:54:10.652940Z  INFO dispatch: mockingbird::deemix: deezer metadata Some(Metadata { track: Some("CtrlAltDelete"), artist: Some("Bones"), date: None, channels: Some(2), channel: None, start_time: None, duration: Some(178s), sample_rate: Some(48000), source_url: None, title: None, thumbnail: None })
May 31 05:54:10 start[421206]: 2023-05-31T09:54:10.780770Z  INFO dispatch: mockingbird::deemix: load time: 0.127666098
May 31 05:54:10 start[421206]: 2023-05-31T09:54:10.780936Z  INFO dispatch: songbird::tracks::queue: Track added to queue.
May 31 05:54:10 start[421206]: 2023-05-31T09:54:10.796020Z  INFO runner: songbird::driver::tasks::events: Event state for track 2 added
May 31 05:56:22 start[421206]: 2023-05-31T09:56:22.216048Z  INFO runner: songbird::events::store: Firing End for [0]
May 31 05:56:22 start[421206]: 2023-05-31T09:56:22.216244Z  INFO runner: songbird::tracks::queue: Queued track ended: Track([(TrackState { playing: End, volume: 1.0, position: 174.4s, play_time: 174.4s, loops: Finite(0) }, TrackHandle { inner: InnerHandle { command_channel: Sender, seekable: false, uuid: a803e0b7-ff1e-4c15-b620-11ec476e556e, metadata: Metadata { track: Some("BedfordFalls"), artist: Some("Bones"), date: None, channels: Some(2), channel: None, start_time: None, duration: Some(174s), sample_rate: Some(48000), source_url: None, title: None, thumbnail: None }, typemap: "<LOCK>" } })]).
May 31 05:56:22 start[421206]: 2023-05-31T09:56:22.216391Z  INFO runner: songbird::tracks::queue: 1 tracks remain.
May 31 05:56:22 start[421206]: 2023-05-31T09:56:22.219827Z  INFO runner: songbird::driver::tasks::events: Event state for track 0 of 2 removed.
May 31 05:56:22 start[421206]: 2023-05-31T09:56:22.235473Z  INFO runner: songbird::events::store: Firing Play for [0]
May 31 05:57:05 start[421206]: 2023-05-31T09:57:05.556052Z  INFO runner: songbird::events::store: Firing End for [0]
May 31 05:57:05 start[421206]: 2023-05-31T09:57:05.557692Z  INFO runner: songbird::tracks::queue: Queued track ended: Track([(TrackState { playing: End, volume: 1.0, position: 43.32s, play_time: 43.32s, loops: Finite(0) }, TrackHandle { inner: InnerHandle { command_channel: Sender, seekable: false, uuid: c4d7a348-4941-45ba-b387-81967598ba3e, metadata: Metadata { track: Some("CtrlAltDelete"), artist: Some("Bones"), date: None, channels: Some(2), channel: None, start_time: None, duration: Some(178s), sample_rate: Some(48000), source_url: None, title: None, thumbnail: None }, typemap: "<LOCK>" } })]).
May 31 05:57:05 start[421206]: 2023-05-31T09:57:05.557821Z  INFO runner: songbird::tracks::queue: 0 tracks remain.
May 31 05:57:05 start[421206]: 2023-05-31T09:57:05.560220Z  INFO runner: songbird::driver::tasks::events: Event state for track 0 of 1 removed.
May 31 05:57:05 start[421206]: 2023-05-31T09:57:05.635381Z  INFO runner{evt_rx=Receiver ssrc=751826 heartbeat_interval=13750.0 attempt_idx=1 info=ConnectionInfo { channel_id: Some(ChannelId(942432077712863295)), endpoint: "us-central6509.discord.media:443", guild_id: GuildId(942432077079535656), session_id: "3712b981d4a0fd00e00386823f1e4a72", token: "<secret>", user_id: UserId(461359650496053258) }}:run{interconnect=Interconnect { core: Sender, events: Sender, mixer: Sender }}: songbird::driver::tasks::ws: Changing to (empty)

full transaction log with known errors https://gist.github.com/Skarlett/c054d949dac152fe82d70cb2386efb96

The bug only seems to appear when multiple items are queued to play.

Prime suspect causes so far.

the bug is reproducible using ytdl, though still unsure of the cause.

some ideas are:

Steps to reproduce: I haven't not yet found a viable method for reproduction.

Skarlett commented 1 year ago

After given some thought, I believe the prime suspect of this problem is the underlying process is being closed before its competition. When I have an opportunity, I'll make sure to add logging capabilities for stderr on ffmpeg & deemix-stream. I'll post my findings shortly after.

Skarlett commented 1 year ago

will switch to next branch

Skarlett commented 1 year ago

Solution was to stick cat in-between the process chain.

source process was timing out the connection. cat acts as a container buffer.