Repeated channel_join rate limit messages

[Pidgeot]

I wrote a simple little bot for a streamer I'm a moderator for. After a while, even with no activity in the channel, I start getting messages like this

Bucket channel_join got rate limited. wating 10.00s...
Bucket channel_join got rate limited. wating 10.00s...
Bucket channel_join got rate limited. wating 10.00s...
Bucket channel_join got rate limited. wating 10.00s...
failed to join the following channel of the initial following list: mioschannel, mioschannel, mioschannel, mioschannel, mioschannel
Bucket channel_join got rate limited. wating 10.00s...
Bucket channel_join got rate limited. wating 10.00s...
Bucket channel_join got rate limited. wating 10.00s...

I don't really get why this is happening - I'm only joining the one channel anyway, and it is in the channel, so I don't know why it would keep trying to join, or why it seems to be doing it more than once (given that the "initial following list" keeps growing with every wait). It seems to usually fix itself, at least for a while, but it doesn't feel like that should happen in the first place.

I removed irrelevant bits of my script and pasted the rest below - am I doing something wrong here that I'm just not seeing? It's mostly taken straight from the documentation example, so I wouldn't think so...

#!/usr/bin/python3

APP_ID = '<appid>'
APP_SECRET = '<secret>'
CHANNEL = 'MiosChannel'

from twitchAPI.twitch import Twitch
from twitchAPI.oauth import UserAuthenticator
from twitchAPI.types import AuthScope, ChatEvent
from twitchAPI.chat import Chat, EventData, ChatMessage, ChatSub, ChatCommand, ChatUser

import asyncio, json, os

USER_SCOPE = [AuthScope.CHAT_READ, AuthScope.CHAT_EDIT]

async def on_ready(ready_event: EventData):
    print("Connecting to channel")
    await ready_event.chat.join_room(CHANNEL)

async def update_tokens(token, refresh_token):
    with open('token.json', 'w') as _f:
        json.dump({'token': token, 'refresh': refresh_token}, _f)

async def run():
    twitch = await Twitch(APP_ID, APP_SECRET)
    twitch.user_auth_refresh_callback = update_tokens
    needs_auth = True
    if os.path.exists('token.json'):
        try:
            with open('token.json', 'r') as _f:
                creds = json.load(_f)
                await twitch.set_user_authentication(creds['token'], USER_SCOPE, creds['refresh'])
        except:
            print("New tokens required, refreshing")
        else:
            needs_auth = False
    if needs_auth:
        auth = UserAuthenticator(twitch, USER_SCOPE, url="http://localhost/twitchauth.php")
        print("Authenticate here: " + auth.return_auth_url())
        user_token = input("Enter generated token: ")
        token, refresh_token = await auth.authenticate(user_token=user_token)
        await update_tokens(token, refresh_token)
        await twitch.set_user_authentication(token, USER_SCOPE, refresh_token)

    chat = await Chat(twitch)
    chat.register_event(ChatEvent.READY, on_ready)
    chat.start()
    try:
        input('press ENTER to stop\n')
    finally:
        chat.stop()
        await twitch.close()

asyncio.run(run())

This is happening both using the most recent release (3.11.0) and with the latest source code directly from GitHub (with the appropriate change from twitchAPI.types to twitchAPI.type). In case it makes a difference, it's running on Gentoo Linux (a server I have around for stuff like this).

[Teekeks]

The rate limit warnings can be ignored since they are just informing you that you are waiting for the bucket to be opened again (this is unavoidable when trying to join a lot of channels quickly).

They should probably not be a warning though but something like info or debug.

[Pidgeot]

Sure... but again, I'm only trying to join one channel, and it's right at startup. There's no dynamic joining or anything.

So how does the bucket get filled up in the first place? And why would it list the same channel multiple times in one output line?

[Teekeks]

oh, now I get the problem. yes thats indeed not intended behaviour :D

[Teekeks]

Can you try to set the logging level to debug and then look out for any messages that read like got NOTICE for channel [...]?

[Pidgeot]

I'm still waiting to see the exact issue again, but I did notice this in what I've been logging so far:

DEBUG:twitchAPI.chat:websocket is closing
DEBUG:twitchAPI.chat:reconnecting...
DEBUG:twitchAPI.chat:> "CAP REQ :twitch.tv/membership twitch.tv/tags twitch.tv/commands"
DEBUG:twitchAPI.chat:> "PASS oauth:<redacted>"
DEBUG:twitchAPI.chat:> "NICK <redacted>"
DEBUG:twitchAPI.chat:< :tmi.twitch.tv CAP * ACK :twitch.tv/membership twitch.tv/tags twitch.tv/commands
DEBUG:twitchAPI.chat:got CAP reply, granted caps: twitch.tv/membership twitch.tv/tags twitch.tv/commands
DEBUG:twitchAPI.chat:< :tmi.twitch.tv 001 <redacted> :Welcome, GLHF!
DEBUG:twitchAPI.chat:< :tmi.twitch.tv 002 <redacted> :Your host is tmi.twitch.tv
DEBUG:twitchAPI.chat:numeric message: 002
002 <redacted>
DEBUG:twitchAPI.chat:< :tmi.twitch.tv 003 <redacted> :This server is rather new
DEBUG:twitchAPI.chat:numeric message: 003
003 <redacted>
DEBUG:twitchAPI.chat:< :tmi.twitch.tv 004 <redacted> :-
DEBUG:twitchAPI.chat:numeric message: 004
004 <redacted>
DEBUG:twitchAPI.chat:< :tmi.twitch.tv 375 <redacted> :-
DEBUG:twitchAPI.chat:numeric message: 375
375 <redacted>
DEBUG:twitchAPI.chat:< :tmi.twitch.tv 372 <redacted> :You are in a maze of twisty passages, all alike.
DEBUG:twitchAPI.chat:numeric message: 372
372 <redacted>
DEBUG:twitchAPI.chat:< :tmi.twitch.tv 376 <redacted> :>
DEBUG:twitchAPI.chat:numeric message: 376
376 <redacted>
DEBUG:twitchAPI.chat:< @badge-info=;badges=;color=;display-name=<redacted>;emote-sets=0,300374282;user-id=945399114;user-type= :tmi.twitch.tv GLOBALUSERSTATE
DEBUG:twitchAPI.chat:got ready event
DEBUG:twitchAPI.chat:> "JOIN #mioschannel,#mioschannel"
DEBUG:twitchAPI.chat:< :<redacted>!<redacted>@<redacted>.tmi.twitch.tv JOIN #mioschannel
DEBUG:twitchAPI.chat:< :<redacted>.tmi.twitch.tv 353 <redacted> = #mioschannel :<redacted>
DEBUG:twitchAPI.chat:< :<redacted>.tmi.twitch.tv 366 <redacted> #mioschannel :End of /NAMES list
DEBUG:twitchAPI.chat:numeric message: 366
366 <redacted> #mioschannel
DEBUG:twitchAPI.chat:< @badge-info=;badges=vip/1;color=;display-name=<redacted>;emote-sets=0,300374282;mod=0;subscriber=0;user-type= :tmi.twitch.tv USERSTATE #mioschannel
DEBUG:twitchAPI.chat:< @emote-only=1;followers-only=-1;r9k=0;room-id=769035392;slow=0;subs-only=0 :tmi.twitch.tv ROOMSTATE #mioschannel
DEBUG:twitchAPI.chat:got user state event
DEBUG:twitchAPI.chat:got room state event
DEBUG:twitchAPI.chat:< :<redacted>!<redacted>@<redacted>.tmi.twitch.tv JOIN #mioschannel
DEBUG:twitchAPI.chat:< @badge-info=;badges=vip/1;color=;display-name=<redacted>;emote-sets=0,300374282;mod=0;subscriber=0;user-type= :tmi.twitch.tv USERSTATE #mioschannel
DEBUG:twitchAPI.chat:< @emote-only=1;followers-only=-1;r9k=0;room-id=769035392;slow=0;subs-only=0 :tmi.twitch.tv ROOMSTATE #mioschannel
DEBUG:twitchAPI.chat:got user state event
DEBUG:twitchAPI.chat:got room state event
DEBUG:twitchAPI.chat:< :<redacted>.tmi.twitch.tv 353 <redacted> = #mioschannel :<redacted>
DEBUG:twitchAPI.chat:< :<redacted>.tmi.twitch.tv 366 <redacted> #mioschannel :End of /NAMES list
DEBUG:twitchAPI.chat:numeric message: 366
366 <redacted> #mioschannel
INFO:twitchAPI.chat:done joining initial channels

Something about losing the websocket connection seems to make it duplicate the channel list... and this only starts happening after the second disconnect. There was what looked like a third disconnect later, and now the channel was listed four times in the JOIN command.

As to why it keeps disconnecting... I don't know, but I've noticed that in my browser too if there's no activity. So it's probably an issue with my ISP or router (even though the ping/pong process occurs...), but it's not something I think I can easily fix on my end.

Oh, and in case it wasn't clear: there were no messages like the one you mentioned. It seems to be entirely down to the connection loss.

[Teekeks]

using initial_channel (see here: https://pytwitchapi.readthedocs.io/en/stable/modules/twitchAPI.chat.html#twitchAPI.chat.Chat.__init__ ) instead of joining in on_ready would probably fix that for now btu this is def a bug in the logic.

[Pidgeot]

I removed on_ready entirely and changed the chat initialization to chat = await Chat(twitch, initial_channel=[CHANNEL]).

If anything, it seems to have made it worse, because now the list was doubled on the first reconnect. Logs are otherwise identical to the above.

[Teekeks]

Good catch, the commit above should fix this behavior

[Pidgeot]

Seems to work well! I think you might also need to lowercase initial_list in Chat.init, because there was a duplicate after a reconnect when I used the mixed case name instead - but only the one, and it didn't grow beyond that. So it's pretty easy to workaround for the caller anyway.

Using the on_ready method works fine even with mixed case, so sticking to that is also an option.

[Teekeks]

added in 412caca2435b1356f82721ab55aa62e67fe02333