IndexError in RequestHandler

[Harmon758]

While running a server with aiohttp 3.0.1 using Python 3.6 on Windows 7, I'm occasionally encountering this error:

Task exception was never retrieved
future: <Task finished coro=<RequestHandler.start() done, defined at C:\Program Files\Python36\lib\site-packages\aiohttp\web_protocol.py:340> exception=IndexError('pop from an empty deque',)>
Traceback (most recent call last):
  File "C:\Program Files\Python36\lib\site-packages\aiohttp\web_protocol.py", line 365, in start
    message, payload = self._messages.popleft()
IndexError: pop from an empty deque

I'm not sure what requests are causing this, but it seems to be because it's possible for the Cython version of the HTTPRequestParser to return an empty tuple for messages through HTTPParser's feed_data.

[pfreixes]

This part has been refactorized in Aiohttp 3.X so its susceptible to have a bug. You could try to run the same server with the last 2.X series of Aiohttp and see if the error persists, it will allow us to narrow a bit the issue.

Regarding the Cython version, you can always change the version of run Aiohttp using the pure Python implementation disabling them using the environ variable AIOHTTP_NO_EXTENSIONS=1.

I don't know how difficult is narrow the issue in terms of request that triggers that error, but for us, this information is worth it and will help us a lot to find a likely bug.

PD: TBH I don't think that the Cython version is related, but in any case, you can always the previous recipe.

[Harmon758]

You could try to run the same server with the last 2.X series of Aiohttp and see if the error persists

The problem with this is that I'm using an AppRunner instead of run_app because I need to share the event loop with other parts of the program and run_app is blocking. Since AppRunner isn't in 2.X, I'd rather not have to change my program and go through setting up a workaround by mimicking run_app. This was actually a big part of why I waited until 3.X to set up this server.

Regarding the Cython version, you can always change the version of run Aiohttp using the pure Python implementation disabling them using the environ variable AIOHTTP_NO_EXTENSIONS=1.

I'll try this and see if it still occurs. The error occurs pretty sporadically though; sometimes a few times a day, sometimes once every few days. So if it doesn't occur, I'll have to run it for about a week before I'm sure it's not in the pure Python implementation.

I don't know how difficult is narrow the issue in terms of request that triggers that error, but for us, this information is worth it and will help us a lot to find a likely bug.

I'm not sure how to properly determine the details of the request. It doesn't even show up in the access log when it errors. I'm not averse to modifying my local version of aiohttp, so if there's a better way to debug it, just let me know and I can try it out.

[Harmon758]

It just occurred using the pure Python implementation, so it's not just the Cython version.

[webknjaz]

@Harmon758 do you have some error reporting set up? Smth like Sentry is good for getting more context out of error.

[Harmon758]

I don't, because it's a small server I'm running locally, specifically for callbacks/webhooks that it's expecting requests from. I expect the requests that are erroring are some of the port scraper ones that I'm 400'ing on. I don't have any experience using Sentry, but I can try to see if I can set something up though.

[Harmon758]

I tried printing the data passed to feed_data when it returns an empty messages, but it seemed to be junk data:

b'\r\n\r\n'
b'HELP\r\n'
b'TNMP\x04\x00\x00\x00TNME\x00\x00\x04\x00'
b'GIOP\x01\x00\x01\x00$\x00\x00\x00\x00\x00\x00\x00\x01\x00\x00\x00\x01\x00\x00\x00\x06\x00\x00\x00abcdef\x00\x00\x04\x00\x00\x00get\x00\x00\x00\x00\x00'
b'\r\n'
b'\r\n\r\n\r\n\r\n\r\n\r\n'
b'\r\n\r\n\r\n\r\n\r\n\r\n\r\n'
b'\r\n\r\n\r\n\r\n'
b'USER test +iw test :Test Wuz Here\nNICK vldbrezyt\n'
b'U\x00\x00\x00D\xac\x0b\xc6\x88\xca67~\x87j\xfe"(\x00\xc8E\xc9@^\xeb\x9eGL>y\x01\xc7\xf6\x17\xbdp\x89\x15\x9d\xf6\x12\xb1R\xe7\xc81C\t\x18\xfbfOQ\rZ\x8a\xf5\xa3g\xcb\xc3P\x10m \xea\x07:\xf1\\0\xa1\xbb\xcd\xe6\xb3o\xaa\x8a\xcf\xfe\xcd\xed\xc6\xe1m\xf1\x94r'

I also tried using Sentry with its Raven Python client by initializing it in RequestHandler's __init__ and like so:

            try:
                message, payload = self._messages.popleft()
            except IndexError:
                self.raven_client.captureException()

but it doesn't seem to provide any meaningful information.
I'll try using it in the HTTPRequestParser itself and see if that will shed any light.

[Harmon758]

There were breadcrumbs from Sentry this time, but I think it was data from websockets.protocol, from an irrelevant part of my program.

[webknjaz]

It reminds me of IRC commands.

I've found similar log reports at

• https://security.stackexchange.com/questions/162782/apache-strange-requests-in-logs/162792#162792
• https://www.linuxquestions.org/questions/blog/habitual-558710/exploit-permissions-36774/#comment41602

looks like a hacked up version of nmap's ircServerInfo.nse script

• https://www.badcaps.net/forum/showthread.php?t=62908#post753110
• http://carnal0wnage.attackresearch.com/2007/08/nmaps-ircserverinfo-script.html
• https://whatismyipaddress.com/ip/164.52.0.141

It looks like wide-range checking of vulnerable web(IRC?)-services by sending

[asvetlov]

Fixed by #2752