EventSub produces errors when running into timeout

[Daenara]

Evening,

a while ago my local test setup using nginx as a reverse proxy broke in a way that ends up with EventSub having a 1 in 100 chance of working, otherwise it just runs into a timeout. Now I know my broken setup is my problem, but pyTwitchAPI actually seems to be trying to continue to do stuff with EventSub, even if the initial connect ran into a timeout. Those periodic errors seem like something that should be fixed, or at least looked at.

2022-08-11 22:32:04,760 aiohttp.server ERROR: Error handling request
Traceback (most recent call last):
  File "L:\Seafile\Programmieren\Python\venv\TwitchBot\lib\site-packages\aiohttp\web_protocol.py", line 435, in _handle_request
    resp = await request_handler(request)
  File "L:\Seafile\Programmieren\Python\venv\TwitchBot\lib\site-packages\aiohttp\web_app.py", line 504, in _handle
    resp = await handler(request)
  File "L:\Seafile\Programmieren\Python\venv\TwitchBot\lib\site-packages\twitchAPI\eventsub.py", line 290, in __handle_callback
    return await self.__handle_challenge(request, data)
  File "L:\Seafile\Programmieren\Python\venv\TwitchBot\lib\site-packages\twitchAPI\eventsub.py", line 284, in __handle_challenge
    self.__activate_callback(data.get('subscription').get('id'))
  File "L:\Seafile\Programmieren\Python\venv\TwitchBot\lib\site-packages\twitchAPI\eventsub.py", line 226, in __activate_callback
    self.__callbacks[c_id]['active'] = True
KeyError: '8763fd0c-627e-4e9e-a534-3a662346c56d'

Those errors only appear in my log sometimes, even though I almost always run into the timeout because of my broken setup. I never have my test setup running for long, since I normally only start it up to make sure my changes didn't break anything before I move the changes to the server, so I have no idea if they appear in any frequency, they just appear.

Daenara

[Teekeks]

oh thats interesting, do you have any more detail in what way your setup is broken?

[Daenara]

If I knew how it was broken, I would fix it. All I know is it worked fine, I updated the pi it is running on a few times but didn't work on the twitch bot, and when I started again I only got timeouts. Since it runs fine on the server it has to be my setup. The really strange thing is, that it sometimes gets through, but I have to restart the bot for an hour to get it working once. Since it works sometimes, it can't be completely broken but it isn't working right, either.

[tit0uanf]

It happened to me when subscribing to multiple events take more than 60s to end. I fixed it by setting wait_for_subscription_confirm: bool = True to False in eventsub.py

[Teekeks]

Does this problem still exist in the current versions?

[scojosmith]

It would appear so. I got the same error, so I updated to the latest version, and it went away when I set event_sub.wait_for_subscription_confirm = False

[Teekeks]

@scojosmith can you please provide a code example which triggers this bug?

[scojosmith]

I'm in the very early stages of implementing EventSub, but it's like TFori said, it happens when you subscribe to multiple events back-to-back:

    # create the api instance and get the ID of the target user
    twitch = await Twitch(CLIENT_ID, CLIENT_SECRET)
    user = await first(twitch.get_users(logins=TARGET_USERNAME))

    # basic setup, will run on port 8080 and a reverse proxy takes care of the https and certificate
    event_sub = EventSub(EVENTSUB_URL, APP_ID, PORT, twitch)
    # event_sub.wait_for_subscription_confirm = False # uncommenting this line removes the error from my logs
    # unsubscribe from all old events that might still be there
    # this will ensure we have a clean slate
    await event_sub.unsubscribe_all()
    # start the eventsub client
    event_sub.start()
    # subscribing to the desired eventsub hook for our user
    # the given function will be called every time this event is triggered
    await event_sub.listen_channel_follow(user.id, on_event)
    await event_sub.listen_stream_online(user.id, on_event)
    await event_sub.listen_hype_train_begin(user.id, on_event)
    await event_sub.listen_hype_train_end(user.id, on_event)
    await event_sub.listen_hype_train_progress(user.id, on_event)

[Teekeks]

And do you get EventSubSubscriptionTimeout or do you get a KeyError?

[scojosmith]

KeyError

[scojosmith]

You've got me wondering now whether or not I had that error on the latest version. It's possible my deploy included both the commit setting event_sub.wait_for_subscription_confirm = False and the one upgrading to the latest. I'll double-check.

[scojosmith]

I redeployed with event_sub.wait_for_subscription_confirm = False and got the error:

2023-01-24T23:35:50.325-07:00   DEBUG:twitchAPI.twitch:making DELETE request to https://api.twitch.tv/helix/eventsub/subscriptions?id=ab591c35-XXXX-40f4-b642-ab366b38cd6a
2023-01-24T23:35:50.425-07:00   DEBUG:asyncio:Using selector: EpollSelector
2023-01-24T23:35:50.425-07:00   DEBUG:twitchAPI.eventsub:subscribe to channel.follow version 1 with condition {'broadcaster_user_id': '#########'}
2023-01-24T23:35:50.426-07:00   INFO:twitchAPI.eventsub:started twitch API event sub on port 8000
2023-01-24T23:37:01.749-07:00   DEBUG:twitchAPI.eventsub:received challenge for subscription 54a38b38-XXXX-4b15-998f-febdfbcafdf5
2023-01-24T23:37:01.752-07:00   ERROR:aiohttp.server:Error handling request
2023-01-24T23:37:01.752-07:00   Traceback (most recent call last):
2023-01-24T23:37:01.752-07:00   File "/usr/local/lib64/python3.8/site-packages/aiohttp/web_protocol.py", line 433, in _handle_request
2023-01-24T23:37:01.752-07:00   resp = await request_handler(request)
2023-01-24T23:37:01.752-07:00   File "/usr/local/lib64/python3.8/site-packages/aiohttp/web_app.py", line 504, in _handle
2023-01-24T23:37:01.752-07:00   resp = await handler(request)
2023-01-24T23:37:01.752-07:00   File "/usr/local/lib/python3.8/site-packages/twitchAPI/eventsub.py", line 320, in __handle_callback
2023-01-24T23:37:01.752-07:00   return await self.__handle_challenge(request, data)
2023-01-24T23:37:01.752-07:00   File "/usr/local/lib/python3.8/site-packages/twitchAPI/eventsub.py", line 314, in __handle_challenge
2023-01-24T23:37:01.752-07:00   self.__activate_callback(data.get('subscription').get('id'))
2023-01-24T23:37:01.752-07:00   File "/usr/local/lib/python3.8/site-packages/twitchAPI/eventsub.py", line 254, in __activate_callback
2023-01-24T23:37:01.752-07:00   self.__callbacks[c_id]['active'] = True
2023-01-24T23:37:01.752-07:00   KeyError: '54a38b38-XXXX-4b15-998f-febdfbcafdf5'
2023-01-24T23:37:01.752-07:00   INFO:aiohttp.access:169.254.175.249 [25/Jan/2023:06:37:01 +0000] "POST /callback HTTP/1.1" 500 244 "-" "Go-http-client/1.1"

Bear in mind, I don't have a successful test of my on_event handler yet. My service passes health checks on 8000, but none of the events I'm listening for have actually happened yet. Hopefully, I'll have logs tomorrow.

[Teekeks]

oh that's helpful, looks like the internal webserver is not started up at the time of the first subscription.

temporary fix: add a await asyncio.sleep(1) after the event_sub.start()

[Teekeks]

A potential fix should be available. @scojosmith, @TFori and @Daenara please update to version 3.6.0 and see if this has been fixed

[tit0uanf]

Looks like not

Subscribing to hooks...
Subscribing to streamer2 with id 50637171
subscribe to stream.online version 1 with condition {'broadcaster_user_id': '50637171'}
received challenge for subscription e139da16-21e3-4a7c-ad68-ba6e4c4c15c8
subscribe to stream.offline version 1 with condition {'broadcaster_user_id': '50637171'}
received challenge for subscription a1a0d545-57fe-41f8-b693-2159de837dd4
Subscribing to streamer1 with id 46514053
subscribe to stream.online version 1 with condition {'broadcaster_user_id': '46514053'}
received challenge for subscription 9445fe6b-4aa2-44db-896c-8397a837d8d4
Error handling request
Traceback (most recent call last):
  File "/Users/t2/VITA/V_Checker/vchecker/lib/python3.10/site-packages/aiohttp/web_protocol.py", line 433, in _handle_request
    resp = await request_handler(request)
  File "/Users/t2/VITA/V_Checker/vchecker/lib/python3.10/site-packages/aiohttp/web_app.py", line 504, in _handle
    resp = await handler(request)
  File "/Users/t2/VITA/V_Checker/twitchAPI/eventsub.py", line 322, in __handle_callback
    return await self.__handle_challenge(request, data)
  File "/Users/t2/VITA/V_Checker/twitchAPI/eventsub.py", line 316, in __handle_challenge
    self.__activate_callback(data.get('subscription').get('id'))
  File "/Users/t2/VITA/V_Checker/twitchAPI/eventsub.py", line 256, in __activate_callback
    self.__callbacks[c_id]['active'] = True
KeyError: '9445fe6b-4aa2-44db-896c-8397a837d8d4'

async def start_twitch_stream():
    twitch = await Twitch(APP_ID, APP_SECRET)
    await twitch.authenticate_app([])
    PORT_6001 = 6001
    TARGET_USERNAME_LIST = config['streamers']['streamers_list'].split(",")
    print("Streamers lsit is : %s "% TARGET_USERNAME_LIST)
    WEBHOOK_URL = init_ngrok(PORT_6001)

    hook = EventSub(WEBHOOK_URL, APP_ID, PORT_6001, twitch)
    logger = hook.logger
    logger.setLevel(logging.DEBUG)
    handler = logging.StreamHandler()
    logger.addHandler(handler)

    await hook.unsubscribe_all()
    hook.start()

    users = twitch.get_users(logins=TARGET_USERNAME_LIST)
    print('Subscribing to hooks...')
    async for user in users:
        print("Subscribing to %s with id %s" % (user.display_name,user.id))
        await hook.listen_stream_online(user.id, handle_event_ON_OFF)
        await hook.listen_stream_offline(user.id, handle_event_ON_OFF)

    try:
        await wait_for_event(hook,twitch)
    finally:
       await hook.stop()

    print('done')

[Teekeks]

I was finally able to reproduce this

[Teekeks]

Please update to 3.6.1 and test again. This fixed it at least for me.

[tit0uanf]

Yep it works !

[Teekeks]

I am closing this issue now since it seems to be fixed. please reopen if the same issue pops up again.