Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Button interactions randomly failing after some time #2756

Open
2 tasks done
Armynator opened this issue Oct 17, 2024 · 12 comments
Open
2 tasks done

Button interactions randomly failing after some time #2756

Armynator opened this issue Oct 17, 2024 · 12 comments
Labels
status: need more info in need of additional details

Comments

@Armynator
Copy link

General Troubleshooting

  • I have checked for similar issues on the Issue-tracker.
  • I have checked for PRs that might already address this issue.

Version of JDA

5.1.2

Expected Behaviour

Sometimes button interactions randomly start failing and won't work anymore until a full bot restart. This happens seemingly randomly, sometimes after a few hours, sometimes after a few days of the bot running without a restart.

The interactions sometimes only fail in some channels. Sometimes they start failing in all.

Nothings happens, no event is fired, just the error is logged: java.lang.IllegalStateException: Failed to create channel instance for interaction! Channel Type: 0

I've pasted the full stack trace below, with some details such as the exact channel data removed.
After restarting the bot, the same interactions suddenly all work again.

Code Example for Reproduction Steps

public class ButtonCommandsListener implements EventListener {
    @Override
    public void onEvent(GenericEvent event) {
        if (!(event instanceof final net.dv8tion.jda.api.events.interaction.component.ButtonInteractionEvent buttonInteractionEvent)) {
            return;
        }
        buttonInteractionEvent.reply("Test").setEphemeral(true).queue();
    }
}

Code for JDABuilder or DefaultShardManagerBuilder used

jda = JDABuilder.createLight(token)
                .setAutoReconnect(true)
                .enableIntents(GatewayIntent.MESSAGE_CONTENT)
                .enableIntents(GatewayIntent.GUILD_MEMBERS)
                .addEventListeners(new ReadyListener())
                .addEventListeners(new UserUpdateNameListener())
                .addEventListeners(new UserMessageReceivedListener())
                .addEventListeners(new UserMessageDeletedListener())
                .addEventListeners(new UserRoleChangeListener())
                .addEventListeners(new UserJoinListener())
                .addEventListeners(new UserLeaveListener())
                .addEventListeners(new UserMessageEditedListener())
                .addEventListeners(new ServerEventRedirectListener())
                .addEventListeners(new ButtonCommandsListener())
                .addEventListeners(new SlashCommandListener())
                .build();
jda.awaitReady();

Exception or Error

19:08:01.957 [JDA MainWS-ReadThread] ERROR n.d.j.i.requests.WebSocketClient -- Got an unexpected error. Please redirect the following message to the devs:
        JDA 5.1.2_5f799f1
        INTERACTION_CREATE -> {"entitlements":[],... (REDACTED)
java.lang.IllegalStateException: Failed to create channel instance for interaction! Channel Type: 0
        at net.dv8tion.jda.internal.interactions.InteractionImpl.<init>(InteractionImpl.java:81)
        at net.dv8tion.jda.internal.interactions.DeferrableInteractionImpl.<init>(DeferrableInteractionImpl.java:33)
        at net.dv8tion.jda.internal.interactions.component.ComponentInteractionImpl.<init>(ComponentInteractionImpl.java:48)
        at net.dv8tion.jda.internal.interactions.component.ButtonInteractionImpl.<init>(ButtonInteractionImpl.java:33)
        at net.dv8tion.jda.internal.handle.InteractionCreateHandler.handleAction(InteractionCreateHandler.java:134)
        at net.dv8tion.jda.internal.handle.InteractionCreateHandler.handleInternally(InteractionCreateHandler.java:86)
        at net.dv8tion.jda.internal.handle.SocketHandler.handle(SocketHandler.java:39)
        at net.dv8tion.jda.internal.requests.WebSocketClient.onDispatch(WebSocketClient.java:1009)
        at net.dv8tion.jda.internal.requests.WebSocketClient.onEvent(WebSocketClient.java:892)
        at net.dv8tion.jda.internal.requests.WebSocketClient.handleEvent(WebSocketClient.java:870)
        at net.dv8tion.jda.internal.requests.WebSocketClient.onBinaryMessage(WebSocketClient.java:1048)
        at com.neovisionaries.ws.client.ListenerManager.callOnBinaryMessage(ListenerManager.java:385)
        at com.neovisionaries.ws.client.ReadingThread.callOnBinaryMessage(ReadingThread.java:276)
        at com.neovisionaries.ws.client.ReadingThread.handleBinaryFrame(ReadingThread.java:996)
        at com.neovisionaries.ws.client.ReadingThread.handleFrame(ReadingThread.java:755)
        at com.neovisionaries.ws.client.ReadingThread.main(ReadingThread.java:108)
        at com.neovisionaries.ws.client.ReadingThread.runMain(ReadingThread.java:64)
        at com.neovisionaries.ws.client.WebSocketThread.run(WebSocketThread.java:45)
@freya022
Copy link
Contributor

freya022 commented Oct 17, 2024

I assume this is due to the interaction channel not being in the cache

If you have a way of checking after the error, try to inspect the channel cache, see which channels may be missing, also try another channel

Enable trace logs for the net.dv8tion.jda.internal.requests package, so you can see if there's a point in which the channel was deleted, the general goal being to reconstitute what happened exactly

Sample logback.xml

This config below will save the package's logs to a file, other logs will remain in the console

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true"> <!-- Reloads every minute -->
    <timestamp key="bySecond" datePattern="yyyyMMdd'T'HHmmss"/>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %boldCyan(%-26.-26thread) %boldYellow(%-20.-20logger{0}) %highlight(%-6level) %msg%n%throwable</pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logs/latest.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- daily rollover -->
            <fileNamePattern>logs/logs-%d{yyyy-MM-dd}.log</fileNamePattern>

            <!-- keep 90 days worth of history capped at 3GB total size -->
            <maxHistory>90</maxHistory>
            <totalSizeCap>3GB</totalSizeCap>
        </rollingPolicy>

        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %-26.-26thread %-20.-20logger{0} %-6level %msg%n%throwable</pattern>
        </encoder>
    </appender>

    <!-- JDA -->
    <logger name="net.dv8tion.jda.internal.requests" level="trace" additivity="false">
        <appender-ref ref="FILE"/>
    </logger>

    <!-- All the remaining loggers -->
    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

@MinnDevelopment MinnDevelopment added the status: need more info in need of additional details label Nov 10, 2024
@Armynator
Copy link
Author

Armynator commented Dec 10, 2024

I've changed the logging in October, updated to JDA 5.2.1 in the meantime and it happened multiple times, last incident being today, with no clear reason in the logs.

Channel was created (id 1315832097482477640) today at 00:06 UTC and renamed directly afterwards:

00:06:58.892 [JDA RateLimit-Elastic-Worker 1004] TRACE n.d.jda.internal.requests.Requester -- Sending request on route POST/guilds/REDACTED/channels with body {REDACTED, "name":"ticket-","type":0}
00:06:58.893 [JDA RateLimit-Elastic-Worker 1004] TRACE n.d.jda.internal.requests.Requester -- Executing request POST https://discord.com/api/v10/guilds/REDACTED/channels
00:06:59.218 [JDA RateLimit-Elastic-Worker 1004] TRACE n.d.jda.internal.requests.Requester -- Finished Request POST https://discord.com/api/v10/guilds/REDACTED/channels with code 201
00:06:59.218 [JDA RateLimit-Elastic-Worker 1004] DEBUG n.d.jda.internal.requests.Requester -- Received response with following cf-rays: [redacted, not sure what this is]
00:06:59.232 [JDA RateLimit-Elastic-Worker 1004] TRACE n.d.jda.internal.requests.Requester -- Sending request on route PATCH/channels/1315832097482477640 with body {"name":"ticket-1315832097482477640"}
00:06:59.233 [JDA RateLimit-Elastic-Worker 1004] TRACE n.d.jda.internal.requests.Requester -- Executing request PATCH https://discord.com/api/v10/channels/1315832097482477640
00:06:59.475 [JDA RateLimit-Elastic-Worker 1004] TRACE n.d.jda.internal.requests.Requester -- Finished Request PATCH https://discord.com/api/v10/channels/1315832097482477640 with code 200
00:06:59.475 [JDA RateLimit-Elastic-Worker 1004] DEBUG n.d.jda.internal.requests.Requester -- Received response with following cf-rays: [redacted, not sure what this is]
00:07:00.121 [JDA MainWS-ReadThread] TRACE n.d.j.i.requests.WebSocketClient -- CHANNEL_CREATE -> { REDACTED ,"id":"1315832097482477640"}

Permissions were set, channel was renamed, button interaction inside the channel was created, audit log entries were created/received, all fine so far.
However, directly afterwards this shows up in the log, probably because of the created button interaction in the channel:

00:07:00.192 [JDA MainWS-ReadThread] DEBUG n.d.jda.internal.handle.EventCache -- Received a message for a channel that JDA does not currently have cached

And the exact same log message repeats from that point onward every time someone is posting a message inside that channel. So to me it looks like the channel was never cached to begin with for some reason.

Interactions with that channel still failed exactly as stated in the initial bug report, at least until a bot restart. This still happens completely randomly, with only a few channels affected every month.

The channels are created like this: (all actions like creation, rename, permission changes etc. are done with .complete())

final TextChannel channel = Guild.createTextChannel("ticket-").addPermissionOverride(...).syncPermissionOverrides().complete();
channel.getManager().setName("ticket-" + channel.getId()).complete();

It uses channel.getId() successfully there and renames the channel, not sure if that hits the cache or works differently.

@MinnDevelopment
Copy link
Member

Are there any more logs for that guild? Are there any logs about reconnecting?

@Armynator
Copy link
Author

The logs get deleted frequently due to very limited disk space. This was the first time I got a full log of this happening. Anything specific I should look for?

There was a reconnect at 01:24, so much later and nowhere near the time around channel creation.

01:23:50.608 [JDA Gateway-Worker 1] TRACE n.d.j.i.requests.WebSocketClient -- <- {"op":1,"d":REDACTED}
01:23:50.709 [JDA MainWS-ReadThread] TRACE n.d.j.i.requests.WebSocketClient -- Got Heartbeat Ack (OP 11).
01:24:05.979 [JDA MainWS-ReadThread] DEBUG n.d.j.i.requests.WebSocketClient -- Got Reconnect request (OP 7). Closing connection now...
01:24:06.084 [JDA MainWS-ReadThread] DEBUG n.d.j.i.requests.WebSocketClient -- Got disconnected from WebSocket (Code: 4900). Attempting to resume session
01:24:06.085 [JDA MainWS-ReadThread] DEBUG n.d.j.i.requests.WebSocketClient -- Attempting to reconnect in 0s
01:24:06.085 [JDA MainWS-ReadThread] DEBUG n.d.j.i.requests.WebSocketClient -- Attempting to reconnect!
01:24:06.260 [JDA MainWS-ReadThread] DEBUG n.d.j.i.requests.WebSocketClient -- Connected to WebSocket
01:24:06.260 [JDA MainWS-ReadThread] DEBUG n.d.j.i.requests.WebSocketClient -- Sending Resume-packet...
01:24:06.260 [JDA MainWS-ReadThread] TRACE n.d.j.i.requests.WebSocketClient -- <- {"op":6,"d": REDACTED}
01:24:06.260 [JDA MainWS-ReadThread] DEBUG n.d.j.i.requests.WebSocketClient -- Got HELLO packet (OP 10). Initializing keep-alive.
01:24:06.261 [JDA Gateway-Worker 1] TRACE n.d.j.i.requests.WebSocketClient -- <- {"op":1,"d": REDACTED}
01:24:06.363 [JDA MainWS-ReadThread] TRACE n.d.j.i.requests.WebSocketClient -- RESUMED -> {"_trace":["[\"gateway-prd-us-east1-c-d7h3\",{\"micros\":649,\"calls\":[\"id_created\",{\"micros\":0,\"calls\":[]},\"session_lookup_time\",{\"micros\":310,\"calls\":[]},\"session_lookup_finished\",{\"micros\":14,\"calls\":[]},\"discord-sessions-prd-1-16\",{\"micros\":37}]}]"]}
01:24:06.363 [JDA MainWS-ReadThread] DEBUG net.dv8tion.jda.api.JDA -- Successfully resumed Session!
01:24:06.365 [JDA MainWS-ReadThread] TRACE n.d.j.i.requests.WebSocketClient -- Got Heartbeat Ack (OP 11).

@Matita008 Matita008 mentioned this issue Jan 3, 2025
2 tasks
@Matita008
Copy link

#2788

@Xirado
Copy link
Contributor

Xirado commented Jan 3, 2025

@Armynator Do you still experience this issue?

@Armynator
Copy link
Author

Yes, tried token reset and updated to JDA 5.2.2 in the meantime. Still happening randomly, sometimes after days, sometimes after weeks. Couldn't find any further clues in the trace logs, see the logs I've already posted above. Looks like the problematic channels are never cached to begin with.

If it matters: the channel creation (and all actions performed on it) are done synchronously as in the code example I've already posted above. They all execute fine with a direct reference to the created channel: .setName, .putMemberPermissionOverride, .sendMessageEmbeds, .pinMessageById, ...
I'm also getting the channel directly after creation with getTextChannel() by ID to call sendMessageEmbeds on it just fine. But for some reason, button interactions in/on such a bugged channel will always fail after initial channel creation and configuration, at least until I perform a full bot restart.

@MinnDevelopment
Copy link
Member

Are these channels always channels created by your bot within the same runtime? As in:

  1. Bot process starts
  2. Bot creates channel in the same process
  3. Event fails with above exception

And the consequential followup question: Does it happen for these channels again after the bot restarts or only when they were created within the same process runtime?

Looks like the problematic channels are never cached to begin with.

When a channel is created by JDA, it is cached immediately. If you have a TextChannel object, it was added to cache.

@Armynator
Copy link
Author

Yes, created in the same runtime, failing in the same runtime. After bot restart they work normally again, so this only happens within the same process runtime.

Not sure why the trace log complaints if they are immediately cached then. I assume the missing cache log message shortly after creation appears because of the sendMessageEmbeds call during/after initial channel creation.

00:07:00.121 [JDA MainWS-ReadThread] TRACE n.d.j.i.requests.WebSocketClient -- CHANNEL_CREATE -> { REDACTED ,"id":"1315832097482477640"}
00:07:00.192 [JDA MainWS-ReadThread] DEBUG n.d.jda.internal.handle.EventCache -- Received a message for a channel that JDA does not currently have cached

@MinnDevelopment
Copy link
Member

Would it be possible for you to test if the failing channels are in jda.getChannelById but not in guild.getChannelById?

@DerGruenkohl
Copy link

im experiencing the same issue and I did some testing.
Channels start failing for me after the bot gets disconnected. -> Missed 2 heartbeats! Trying to reconnect...
Mostly the channels that have been created shortly before the bot gets disconnected fail.
Its not just ButtonInteractions that fail, but also SlashCommand interactions.

There may be an issue with the caching when reconnecting

@MinnDevelopment
Copy link
Member

Thank you for the additional information, I have a rough idea what the problem could be now. I'll look into reproducing and potentially fixing the issue some time next week.

@MinnDevelopment MinnDevelopment marked this as a duplicate of #2788 Jan 19, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: need more info in need of additional details
Projects
None yet
Development

No branches or pull requests

6 participants