classification
Title: Asyncio Fatal Error on SSL Transport - IndexError Deque Index Out Of Range
Type: behavior Stage:
Components: asyncio, SSL Versions: Python 3.7
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: christian.heimes Nosy List: asvetlov, ben.brown, christian.heimes, maayank, yselivanov
Priority: normal Keywords:

Created on 2019-06-11 08:44 by ben.brown, last changed 2019-07-22 10:53 by ben.brown.

Messages (17)
msg345201 - (view) Author: Ben Brown (ben.brown) Date: 2019-06-11 08:44
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
msg345202 - (view) Author: Christian Heimes (christian.heimes) * (Python committer) Date: 2019-06-11 08:47
This looks more like an asyncio problem than an SSL problem. Andrew, Yury,  please take a look.
msg345211 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-06-11 09:41
Just to clarify: what OpenSSL version is used?
msg345212 - (view) Author: Ben Brown (ben.brown) Date: 2019-06-11 09:43
The OpenSSL version is OpenSSL 1.1.0j  20 Nov 2018
msg345213 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-06-11 10:00
That's what I afraid.
asyncio/sslproto.py fails on new OpenSSL at several places :(
msg345214 - (view) Author: Ben Brown (ben.brown) Date: 2019-06-11 10:08
That's a shame, which version should it work on I don't mind downgrading for now to fix the issue as a workaround.
msg345215 - (view) Author: Christian Heimes (christian.heimes) * (Python committer) Date: 2019-06-11 10:09
Is 1.1.0 also a problem? I have only seen issue with 1.1.1 and TLS 1.3.
msg345223 - (view) Author: Ben Brown (ben.brown) Date: 2019-06-11 11:22
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.
msg345241 - (view) Author: Ben Brown (ben.brown) Date: 2019-06-11 15:38
I tested an older version of OpenSSL 1.0.2g and I get the same error on that
msg345316 - (view) Author: Ben Brown (ben.brown) Date: 2019-06-12 11:05
I have created a minimal example if that helps to show the issue https://gist.github.com/bobthemac/031213b8e37960ee805f2ae1e6990b60
msg345317 - (view) Author: Andrew Svetlov (asvetlov) * (Python committer) Date: 2019-06-12 11:08
Thank you!
Yuri, you might be interested too
msg346365 - (view) Author: Ben Brown (ben.brown) Date: 2019-06-24 10:38
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.
msg346930 - (view) Author: Maayan Keshet (maayank) Date: 2019-06-30 14:14
Any updates on this issue? We're also encountering it as part of our websocket clients.
msg347564 - (view) Author: Ben Brown (ben.brown) Date: 2019-07-09 16:15
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.
msg347906 - (view) Author: Maayan Keshet (maayank) Date: 2019-07-14 11:12
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.
msg348167 - (view) Author: Ben Brown (ben.brown) Date: 2019-07-19 11:49
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.
msg348294 - (view) Author: Ben Brown (ben.brown) Date: 2019-07-22 10:53
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.
History
Date User Action Args
2019-07-22 10:53:53ben.brownsetmessages: + msg348294
2019-07-19 11:49:09ben.brownsetmessages: + msg348167
2019-07-14 11:12:59maayanksetmessages: + msg347906
2019-07-09 16:15:31ben.brownsetmessages: + msg347564
2019-06-30 14:14:14maayanksetnosy: + maayank
messages: + msg346930
2019-06-24 10:38:40ben.brownsetmessages: + msg346365
2019-06-12 11:08:58asvetlovsetmessages: + msg345317
2019-06-12 11:05:45ben.brownsetmessages: + msg345316
2019-06-11 15:38:34ben.brownsetmessages: + msg345241
2019-06-11 11:22:52ben.brownsetmessages: + msg345223
2019-06-11 10:09:56christian.heimessetmessages: + msg345215
2019-06-11 10:08:56ben.brownsetmessages: + msg345214
2019-06-11 10:00:13asvetlovsetmessages: + msg345213
2019-06-11 09:43:20ben.brownsetmessages: + msg345212
2019-06-11 09:41:20asvetlovsetmessages: + msg345211
2019-06-11 08:47:56christian.heimessetnosy: + asvetlov, yselivanov
messages: + msg345202
components: + asyncio
2019-06-11 08:44:59ben.browncreate