search

Androz2091 / discord-player

🎧 Complete framework to simplify the implementation of music commands using discord.js v14
https://discord-player.js.org/
MIT License
593 stars 190 forks source link

player stucks randomly on queue. #1920

Closed kensunjaya closed 2 months ago

kensunjaya commented 3 months ago

Since last week, player stucks randomly on any queue index. skipping the track doesn't seems to work. After a track ends, the player doesn't continue to the next track on the queue, instead it stops playing audio and stays on the voice channel with no audio. I think it might be a bug on the queue system (?)

player.events.on("playerStart", async (queue, track) => {
    if (guildHandler.get(queue.guild)) {
        // last change here
        try {
            if (guildHandler.get(queue.guild).commandName === 'play' && !queue.tracks.data.length) {
                await guildHandler.get(queue.guild).followUp({embeds : [Embed.musicPlaying(track)]});
            }
            else {
                await guildHandler.get(queue.guild).channel.send({embeds : [Embed.musicPlaying(track)]});
            }
             // guildHandler.set(queue.guild, newInteraction);
        }
        catch (error) {
            console.log(error);
            return void console.log("Error on playerStart : " + error);
        }
        finally {
            console.log("playerStart initiated");
        }
    }

});

image playerInitiated? but the message doesn't seem to be sent on discord. And error doesn't seem to be caught. Anyways I'm new to discord-player. Sorry for any misunderstanding.

twlite commented 3 months ago

how are you playing the track?

retrouser955 commented 3 months ago

Hello @kensunjaya. Could you send your debug logs here?

player.events.on("debug", (queue, msg) => console.log(msg))
player.on('debug', (msg) => console.log(msg))

Also send the following

console.log(player.scanDeps())
kensunjaya commented 3 months ago

how are you playing the track?

if (interaction.commandName === "play" || interaction.commandName === "p") {
        await interaction.deferReply();

        const query = interaction.options.get("query").value;
        const search_engine = interaction.options.get("search_engine");

        let searchResult = await player
            .search(query, {
                requestedBy: interaction.user,
                searchEngine: search_engine ? search_engine.value : QueryType.AUTO,
            })
            .catch(() => {});

        if (!searchResult || !searchResult.tracks.length) {
            if (search_engine && search_engine.type != 3) return void interaction.followUp({ content: "No results were found!" });
            const availableEngines = [QueryType.SPOTIFY_PLAYLIST,
                QueryType.SPOTIFY_ALBUM,
                QueryType.SPOTIFY_SONG]
            if (!search_engine) {
                availableEngines.push(QueryType.YOUTUBE);
                availableEngines.push(QueryType.YOUTUBE_PLAYLIST);
                availableEngines.push(QueryType.SOUNDCLOUD);
            }
            for (let i=0;i<availableEngines.length;i++) {
                searchResult = await player
                .search(query, {
                    requestedBy: interaction.user,
                    searchEngine: availableEngines[i]
                })
                .catch(() => {});
                if (searchResult) break;
            }
            if (!searchResult || !searchResult.tracks.length) {
                return void interaction.followUp({ content: "No results were found!" });
            }
        }

        const queue = player.nodes.create(interaction.guild, {
            metadata: interaction.channel,
            leaveOnEmpty: false,
            leaveOnEnd: false,
            selfDeaf: true,
            selfMute: false,
            volume: 100,
            bufferingTimeout: 3000,
            connectionTimeout: 20000,
            voiceAutoReconnect: true,
        });

        try {
            if (!queue.connection) await queue.connect(interaction.member.voice.channel);
        } catch {
            void player.deleteQueue(interaction.guildId);
            return void interaction.followUp({ content: "Could not join your voice channel!" });
        }

        if (searchResult.playlist) {
            searchResult.playlist.tracks.map(track => {
                queue.addTrack(track);

            });
            await interaction.followUp({embeds : [Embed.addPlaylist(searchResult.playlist)]});
        }
        else {
            queue.addTrack(searchResult.tracks[0]);
        }

        if (!queue.isPlaying()) {
            await queue.node.play(queue.tracks.data[0]);
            guildHandler.set(interaction.guild, interaction);
            queue.removeTrack(queue.tracks.data[0]);
            return;
        }

        if (!searchResult.playlist) {
            await interaction.followUp(`📝 | Added **${searchResult.tracks[0].description}** to queue list`);
        }
    }

Here's the full code: https://github.com/kensunjaya/discord-bot/blob/main/src/index.js

kensunjaya commented 3 months ago

Hello @kensunjaya. Could you send your debug logs here?

player.events.on("debug", (queue, msg) => console.log(msg))
player.on('debug', (msg) => console.log(msg))

Also send the following

console.log(player.scanDeps())

Sure player scandeps.txt debug.txt

On the debug file, the player got stuck at the end. The last track on the debug file didn't even get played

twlite commented 3 months ago

your code is prone to race conditions, please follow this pattern.

const queue = player.nodes.create(...);
const result = await player.search(...);

// acquire task entry
const entry = queue.tasksQueue.acquire();

// wait for previous task to be released and our task to be resolved
await entry.getTask();

// add track(s) (this will add playlist or single track from the result)
queue.addTrack(result);

try {
    // if player node was not previously playing, play a song
    if (!queue.isPlaying()) await queue.node.play();
} finally {
    // release the task we acquired to let other tasks to be executed
    // make sure you are releasing your entry, otherwise your bot won't
    // accept new play requests
    queue.tasksQueue.release();
}
twlite commented 2 months ago

@kensunjaya

from {"status":"playing","missedFrames":0,"playbackDuration":152540,"resource":true,"stepTimeout":false}

after analyzing your log, it seems your bot is indeed playing the track. Do you have your bot muted or something?

twlite commented 2 months ago 
Preparing AudioResource...
Initializing audio player...
state change:
from {"status":"idle","resource":false,"stepTimeout":false}
to {"status":"buffering","resource":true,"stepTimeout":false}
Dispatching audio...
Player triggered for Track {"title":"HAPPY","reason":"normal"}
state change:
from {"status":"buffering","resource":true,"stepTimeout":false}
to {"status":"playing","missedFrames":0,"playbackDuration":0,"resource":true,"stepTimeout":false}
[NW] [WS] >> {"op":5,"d":{"speaking":1,"delay":0,"ssrc":665113}}
playerStart initiated
[NW] [WS] >> {"op":3,"d":1720516274223}
[NW] [WS] << {"op":6,"d":1720516274223}
[NW] [WS] >> {"op":3,"d":1720516287977}
[NW] [WS] << {"op":6,"d":1720516287977}
[Lag Monitor] Event loop latency: 15.844399999827147ms
[NW] [WS] >> {"op":3,"d":1720516301734}
[NW] [WS] << {"op":6,"d":1720516301734}
[NW] [WS] >> {"op":3,"d":1720516315497}
[NW] [WS] << {"op":6,"d":1720516315497}
[Lag Monitor] Event loop latency: 15.849799999967217ms
[NW] [WS] >> {"op":3,"d":1720516329256}
[NW] [WS] << {"op":6,"d":1720516329256}
[NW] [WS] >> {"op":3,"d":1720516343013}
[NW] [WS] << {"op":6,"d":1720516343013}
[Lag Monitor] Event loop latency: 16.007000000216067ms
[NW] [WS] >> {"op":3,"d":1720516356777}
[NW] [WS] << {"op":6,"d":1720516356777}
[NW] [WS] >> {"op":3,"d":1720516370531}
[NW] [WS] << {"op":6,"d":1720516370531}
[NW] [WS] >> {"op":3,"d":1720516384289}
[NW] [WS] << {"op":6,"d":1720516384289}
[Lag Monitor] Event loop latency: 15.714800000190735ms
[NW] [WS] >> {"op":3,"d":1720516398047}
[NW] [WS] << {"op":6,"d":1720516398047}
[NW] [WS] >> {"op":3,"d":1720516411810}
[NW] [WS] << {"op":6,"d":1720516411810}
[Lag Monitor] Event loop latency: 15.012499999720603ms

this essentially means your bot is sending audio

kensunjaya commented 2 months ago

@kensunjaya

from {"status":"playing","missedFrames":0,"playbackDuration":152540,"resource":true,"stepTimeout":false}

after analyzing your log, it seems your bot is indeed playing the track. Do you have your bot muted or something?

Not sure if it's playing the track. the bot is not muted. It just stayed quiet after playing some tracks and the queue remains stuck until I stopped the player (also cleared the queue) and play it again. Then it will eventually got stuck again after playing some tracks.

kensunjaya commented 2 months ago 
Preparing AudioResource...
Initializing audio player...
state change:
from {"status":"idle","resource":false,"stepTimeout":false}
to {"status":"buffering","resource":true,"stepTimeout":false}
Dispatching audio...
Player triggered for Track {"title":"HAPPY","reason":"normal"}
state change:
from {"status":"buffering","resource":true,"stepTimeout":false}
to {"status":"playing","missedFrames":0,"playbackDuration":0,"resource":true,"stepTimeout":false}
[NW] [WS] >> {"op":5,"d":{"speaking":1,"delay":0,"ssrc":665113}}
playerStart initiated
[NW] [WS] >> {"op":3,"d":1720516274223}
[NW] [WS] << {"op":6,"d":1720516274223}
[NW] [WS] >> {"op":3,"d":1720516287977}
[NW] [WS] << {"op":6,"d":1720516287977}
[Lag Monitor] Event loop latency: 15.844399999827147ms
[NW] [WS] >> {"op":3,"d":1720516301734}
[NW] [WS] << {"op":6,"d":1720516301734}
[NW] [WS] >> {"op":3,"d":1720516315497}
[NW] [WS] << {"op":6,"d":1720516315497}
[Lag Monitor] Event loop latency: 15.849799999967217ms
[NW] [WS] >> {"op":3,"d":1720516329256}
[NW] [WS] << {"op":6,"d":1720516329256}
[NW] [WS] >> {"op":3,"d":1720516343013}
[NW] [WS] << {"op":6,"d":1720516343013}
[Lag Monitor] Event loop latency: 16.007000000216067ms
[NW] [WS] >> {"op":3,"d":1720516356777}
[NW] [WS] << {"op":6,"d":1720516356777}
[NW] [WS] >> {"op":3,"d":1720516370531}
[NW] [WS] << {"op":6,"d":1720516370531}
[NW] [WS] >> {"op":3,"d":1720516384289}
[NW] [WS] << {"op":6,"d":1720516384289}
[Lag Monitor] Event loop latency: 15.714800000190735ms
[NW] [WS] >> {"op":3,"d":1720516398047}
[NW] [WS] << {"op":6,"d":1720516398047}
[NW] [WS] >> {"op":3,"d":1720516411810}
[NW] [WS] << {"op":6,"d":1720516411810}
[Lag Monitor] Event loop latency: 15.012499999720603ms

this essentially means your bot is sending audio

Initiating DSP filters pipeline...
Executing onAfterCreateStream hook...
Preparing AudioResource...
Initializing audio player...
state change:
from {"status":"idle","resource":false,"stepTimeout":false}
to {"status":"buffering","resource":true,"stepTimeout":false}
Dispatching audio...
[NW] [WS] >> {"op":3,"d":1720516274223}
[NW] [WS] << {"op":6,"d":1720516274223}
[NW] [WS] >> {"op":3,"d":1720516287977}
[NW] [WS] << {"op":6,"d":1720516287977}
[Lag Monitor] Event loop latency: 15.844399999827147ms
[NW] [WS] >> {"op":3,"d":1720516301734}
[NW] [WS] << {"op":6,"d":1720516301734}
[NW] [WS] >> {"op":3,"d":1720516315497}
[NW] [WS] << {"op":6,"d":1720516315497}
[Lag Monitor] Event loop latency: 15.849799999967217ms
[NW] [WS] >> {"op":3,"d":1720516329256}
[NW] [WS] << {"op":6,"d":1720516329256}
[NW] [WS] >> {"op":3,"d":1720516343013}
[NW] [WS] << {"op":6,"d":1720516343013}
[Lag Monitor] Event loop latency: 16.007000000216067ms
[NW] [WS] >> {"op":3,"d":1720516356777}
[NW] [WS] << {"op":6,"d":1720516356777}
[NW] [WS] >> {"op":3,"d":1720516370531}
[NW] [WS] << {"op":6,"d":1720516370531}
[NW] [WS] >> {"op":3,"d":1720516384289}
[NW] [WS] << {"op":6,"d":1720516384289}
[Lag Monitor] Event loop latency: 15.714800000190735ms
[NW] [WS] >> {"op":3,"d":1720516398047}
[NW] [WS] << {"op":6,"d":1720516398047}
[NW] [WS] >> {"op":3,"d":1720516411810}
[NW] [WS] << {"op":6,"d":1720516411810}
[Lag Monitor] Event loop latency: 15.012499999720603ms

At this point, the bot stops emitting audio

jtpotato commented 2 months ago

Set up a similar logging system on my bot:

Logs that start like this:

[LOG] [NW] [WS] >> {"op":3,"d":1720531426630}
[LOG] [NW] [WS] << {"op":6,"d":1720531426630}

usually results in the bot not emitting audio. I think it might be some kind of keepalive signal for the websockets???

However, the moment we get (after multiple restarts, sometimes randomly)

[LOG] [NW] [WS] >> {"op":5,"d":{"speaking":1,"delay":0,"ssrc":19599}}

there's some sort of status change and the bot starts emitting audio (with the green activity ring too).

Absolutely no clue why this happens.

twlite commented 2 months ago 
Initiating DSP filters pipeline...
Executing onAfterCreateStream hook...
Preparing AudioResource...
Initializing audio player...
state change:
from {"status":"idle","resource":false,"stepTimeout":false}
to {"status":"buffering","resource":true,"stepTimeout":false}
Dispatching audio...
[NW] [WS] >> {"op":3,"d":1720516274223}
[NW] [WS] << {"op":6,"d":1720516274223}
[NW] [WS] >> {"op":3,"d":1720516287977}
[NW] [WS] << {"op":6,"d":1720516287977}
[Lag Monitor] Event loop latency: 15.844399999827147ms
[NW] [WS] >> {"op":3,"d":1720516301734}
[NW] [WS] << {"op":6,"d":1720516301734}
[NW] [WS] >> {"op":3,"d":1720516315497}
[NW] [WS] << {"op":6,"d":1720516315497}
[Lag Monitor] Event loop latency: 15.849799999967217ms
[NW] [WS] >> {"op":3,"d":1720516329256}
[NW] [WS] << {"op":6,"d":1720516329256}
[NW] [WS] >> {"op":3,"d":1720516343013}
[NW] [WS] << {"op":6,"d":1720516343013}
[Lag Monitor] Event loop latency: 16.007000000216067ms
[NW] [WS] >> {"op":3,"d":1720516356777}
[NW] [WS] << {"op":6,"d":1720516356777}
[NW] [WS] >> {"op":3,"d":1720516370531}
[NW] [WS] << {"op":6,"d":1720516370531}
[NW] [WS] >> {"op":3,"d":1720516384289}
[NW] [WS] << {"op":6,"d":1720516384289}
[Lag Monitor] Event loop latency: 15.714800000190735ms
[NW] [WS] >> {"op":3,"d":1720516398047}
[NW] [WS] << {"op":6,"d":1720516398047}
[NW] [WS] >> {"op":3,"d":1720516411810}
[NW] [WS] << {"op":6,"d":1720516411810}
[Lag Monitor] Event loop latency: 15.012499999720603ms

At this point, the bot stops emitting audio

as per this log, the stream is at buffering stage, most likely an issue with the streaming lib you are using.

twlite commented 2 months ago

state change: from {"status":"buffering","resource":true,"stepTimeout":false} to {"status":"playing","missedFrames":0,"playbackDuration":0,"resource":true,"stepTimeout":false}

yes, if you see my message above, it includes these lines

state change:
from {"status":"buffering","resource":true,"stepTimeout":false}
to {"status":"playing","missedFrames":0,"playbackDuration":0,"resource":true,"stepTimeout":false}

this can be used to identify the current stage we are in, in this case playing

twlite commented 2 months ago

@kensunjaya I see your bridge provider is youtube, which youtube library are you using? Can you go through each of these until one works https://github.com/Androz2091/discord-player?tab=readme-ov-file#streaming-library? If none of those work, try looking into https://github.com/retrouser955/discord-player-youtubei

jtpotato commented 2 months ago

this can be used to identify the current stage we are in, in this case playing

For some tracks, this line never appears - I think there are examples of a working and not-working track in the logs in this thread, although I haven't looked very closely.

After some messing around, setting skipFFmpeg: false seems to make it occur much less frequently (haven't run into it yet)

twlite commented 2 months ago

this can be used to identify the current stage we are in, in this case playing

For some tracks, this line never appears - I think there are examples of a working and not-working track in the logs in this thread, although I haven't looked very closely.

After some messing around, setting skipFFmpeg: false seems to make it occur much less frequently (haven't run into it yet)

🙂 if this is the case, then the streaming library you are using failed to stream the content. Streaming it via ffmpeg seems to work for you, you can keep it like that. skipFFmpeg mode is turned on by default to avoid instantiating ffmpeg when alternative way of streaming exists, which saves a lot of resources.

kensunjaya commented 2 months ago

@kensunjaya I see your bridge provider is youtube, which youtube library are you using? Can you go through each of these until one works https://github.com/Androz2091/discord-player?tab=readme-ov-file#streaming-library? If none of those work, try looking into https://github.com/retrouser955/discord-player-youtubei

After some investigations, turns out that it was the youtube library being unstable. I used ytdl-core and when I switched to discord-player-youtubei it became a lot more stable. Thank you for the help