FFmpeg stream unpipes around 20 seconds before end of audio file

[mbilker]

YouTube does not always have an Opus audio file available and any other format I pass to Discordie's FFmpegEncoder. This has been happening recently after some of the SIGTERM and SIGKILL changes were implemented, but I am uncertain if this issue is caused by those changes.

I noticed that the stream never fires an unpipe or end event. The timestamp shows the audio file stopped around 8 seconds from the end of the audio file for a full-length song (approx. 3 minutes).

I am still investigating the cause of this. Turning on FFmpegEncoder's debug does not show an error, but I may need to increase the log verbosity.

[mbilker]

For more information, the encoder initialization is:

      this.encoder = voiceConnection.createExternalEncoder({
        type: 'ffmpeg',
        source: this.url,
        format: 'opus',
        outputArgs: ['-ab', '64000'],
        debug: true,
      });

[mbilker]

This is from https:/mbilker/cardinal-discord/blob/d8aa67615399daf209095ce46f901654d0270b3f/queue/queued-media.js#L89-L101

[mbilker]

Found some log output:

  cardinal:queue QUEUE_ITEM +53s https://www.youtube.com/watch?v=-tRdBsnX4N4
  cardinal:queue fetchYoutubeInfo promise resolve +1s
  cardinal:queue handleQueued +4ms

  cardinal:queued-media stopPlaying +3m -HsOQFVeiGE vorbis
  cardinal:queued-media encoder unpipe +1ms -HsOQFVeiGE vorbis
  cardinal:queued-media stream unpipe +0ms -HsOQFVeiGE vorbis

I discovered I forgot to track when the stream from encoder.play() fires its end event.

[qeled]

How often does that happen?
This may be caused by Discord servers disconnecting you (though it will stay in the channel and autoreconnect if it's just a server change), thus why the library could be cleaning up all resources without firing an end event.
Adding a VOICE_DISCONNECTED handler would clear the case up a bit.

Also for debugging stuff like this I'd additionally recommend logging all library events using Dispatcher.onAny or in case of regular event emitters just hooking the emit method.

[mbilker]

It happens with every non-Opus passthrough song. I am going to debug this with the methods you provided. Thanks for the quick response!

[mbilker]

Okay tested it out on https://www.youtube.com/watch?v=rGd7IEOjk-0

It stopped at 2:41 out of 2:48. No disconnect event fired.

EDIT: Classify the event better.

[mbilker]

I screwed up my logging comment from before. I am sorry. The song never ends, but the timestamp stops updating. I had to manually trigger the unpipe.

EDIT: Updated issue post with more accurate information.

[qeled]

Seems to be an issue with stream behavior changes in newer nodejs versions, can consistently reproduce on v5.11.0+.

[qeled]

This commit seems to be a part of the issue: nodejs/node#6023.

v5.11.0:

spawned: 16340
:: STDOUT :: resume
:: PROCESS :: exit
:: STDOUT :: resume

v5.11.0 with commit rolled back:

spawned: 14756
:: STDOUT :: resume
:: PROCESS :: exit
:: STDOUT :: resume
:: STDOUT :: _socketEnd
stdout end
:: STDOUT :: end
:: STDOUT :: prefinish
:: STDOUT :: finish
process exited with code 0
:: PROCESS :: close
:: STDOUT :: close

[qeled]

Pushed a workaround a7de2f4 to dev branch, will push to master and npm if that fixes it.

Doesn't fix the actual source of the bug, but it seems too deep for me to hunt it down and keeps only happening with ffmpeg processes, things like cat close cleanly.

[mbilker]

Thanks for the investigation. I did upgrade my Arch system between restarts of my bot, and I wasn't playing a lot of non-Opus songs so I never noticed.

[mbilker]

Testing now

[mbilker]

Yep that fixes it! I know it is a hack, but thank you for figuring it out.