Asyncio Fatal Error on SSL Transport - IndexError Deque Index Out Of Range

[benbrown]

BPO	37226
Nosy	@tiran, @asvetlov, @1st1, @maayank

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/tiran'
closed_at = <Date 2019-12-11.09:13:16.236>
created_at = <Date 2019-06-11.08:44:59.522>
labels = ['expert-SSL', 'type-bug', '3.7', 'expert-asyncio']
title = 'Asyncio Fatal Error on SSL Transport - IndexError Deque Index Out Of Range'
updated_at = <Date 2019-12-11.09:13:16.235>
user = 'https://bugs.python.org/benbrown'

bugs.python.org fields:

activity = <Date 2019-12-11.09:13:16.235>
actor = 'ben.brown'
assignee = 'christian.heimes'
closed = True
closed_date = <Date 2019-12-11.09:13:16.236>
closer = 'ben.brown'
components = ['asyncio', 'SSL']
creation = <Date 2019-06-11.08:44:59.522>
creator = 'ben.brown'
dependencies = []
files = []
hgrepos = []
issue_num = 37226
keywords = []
message_count = 17.0
messages = ['345201', '345202', '345211', '345212', '345213', '345214', '345215', '345223', '345241', '345316', '345317', '346365', '346930', '347564', '347906', '348167', '348294']
nosy_count = 5.0
nosy_names = ['christian.heimes', 'asvetlov', 'yselivanov', 'ben.brown', 'maayank']
pr_nums = []
priority = 'normal'
resolution = None
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue37226'
versions = ['Python 3.7']

[benbrown]

I have been getting an intermittent errors when using asyncio with SSL. The error always occurs in the _process_write_backlog method in asyncio's sslproto.py file. I have looked at lots of possibilities as to what the cause is and found that for some reason when in _process_write_backlog's loop the deque seems to be empty, I added some quick terrible hacky code to confirm it fixed the issue and checking at each point it is used wether it is empty fixes the issue, I am unusure as to what causes it to become empty but still run through the loop. The most frequent time it happens is after we have a successful message the client sends a request to join a data stream this request mostly causes the error but sometimes it happens while the client is receiving data. I am currently using python 3.7.1 but have also tested my code on 3.7.3 with the same result.

NOTE: I am currently working on a minimal sample to show the issue easier.

Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f267462e780>
transport: <_SelectorSocketTransport fd=38 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
    File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 689, in _process_write_backlog
    del self._write_backlog[0]
IndexError: deque index out of range

Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f45f802ec88>
transport: <_SelectorSocketTransport fd=29 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
    File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 664, in _process_write_backlog
    data, offset = self._write_backlog[0]
IndexError: deque index out of range

[tiran]

This looks more like an asyncio problem than an SSL problem. Andrew, Yury, please take a look.

[asvetlov]

Just to clarify: what OpenSSL version is used?

[benbrown]

The OpenSSL version is OpenSSL 1.1.0j 20 Nov 2018

[asvetlov]

That's what I afraid.
asyncio/sslproto.py fails on new OpenSSL at several places :(

[benbrown]

That's a shame, which version should it work on I don't mind downgrading for now to fix the issue as a workaround.

[tiran]

Is 1.1.0 also a problem? I have only seen issue with 1.1.1 and TLS 1.3.

[benbrown]

I am using the version I mentioned above 1.1.0 and TLS 1.2, I am sorry I can't be of more help.

[benbrown]

I tested an older version of OpenSSL 1.0.2g and I get the same error on that

[benbrown]

I have created a minimal example if that helps to show the issue https://gist.github.com/bobthemac/031213b8e37960ee805f2ae1e6990b60

[asvetlov]

Thank you!
Yuri, you might be interested too

[benbrown]

Hi is there any update on this issue, were you able to replicate the error with the minimal example I provided or is there any additional information I can provide.

[maayank]

Any updates on this issue? We're also encountering it as part of our websocket clients.

[benbrown]

Maayan Keshet do you have a minimal example it would be interesting to compare against our code and see if there is something we are both doing that could help narrow down the issue.

[maayank]

Hey Ben! Unfortunately our use case is too involved to distill into a neat example. We use a websocket library (autobahn) to connect to a server of a 3rd party which is outside our control (which is not written in python, but rather node.js). We receive the errors on our client.

[benbrown]

With some more research it looks like the issue is flow related, I experimented with the StreamWriter in a simple server and using that plus drain() appears to have worked an I no longer get the error. I have added my new server to the gist I posted above.

[benbrown]

I can fully confirm the issue is due to flow control or lack of in my code the system runs out of resources and this is when it errors, I have implemented flow control in my protocol and it now works without errors. One thing I did find is that the documentation on flow control was lacking but luckily I found this post which makes implementation clearer https://medium.com/@pgjones/an-asyncio-socket-tutorial-5e6f3308b8b0

I am not sure if you would still classify this as a bug the error could be clearer but it could be expected behaviour when you run out of resources, I think this can now be closed I am just unsure of the etiquette as to who closes it and what resolution should be selected.