Elasticsearch-py: urllib3.exceptions.ProtocolError, BadStatusLine

[galuszkak]

urllib3.exceptions.ProtocolError: ('Connection aborted.', BadStatusLine('-inventory_product","_type":"product","_id":"2YmKAWMBhLHMbxOgNI9D","_score":null,"sort":[1663]},{"_index":"synthetic-inventory_product","_type":"product","_id":"3omKAWMBhLHMbxOgNI9D","_score":null,"sort":[1665]},{"_index":"synthetic-inventory_product","_type":"product","_id":"34mKAWMBhLHMbxOgNI9D","_score":null,"sort":[1667]},{"_index":"synthetic-inventory_product","_type":"product","_id":"8ImKAWMBhLHMbxOgNI-Q","_score":null,"sort":[1669]},{"_index":"synthetic-inventory_product","_type":"product","_id":"9ImKAWMBhLHMbxOgNI-Q","_score":null,"sort":[1671]},{"_index":"synthetic-inventory_product","_type":"product","_id":"94mKAWMBhLHMbxOgNI-Q","_score":null,"sort":[1673]}]}}HTTP/1.1 200 OK

So clearly there is some issue that Status code is mixing with response. I'm not sure how this happens but we receive those responses when using celery (not sure if this have any to do with that). I'm not sure if this is Elastic issue, or Python issue, or library issue. I don't know where to start with debugging this, any clues where should I look to find root cause of this?

We are using Elastic 6.0.1 and elasticsearch-dsl==6.1.0 and elasticsearch==6.1.1.

[fxdgear]

@galuszkak I'm afraid that's not enough information. Can you please provide some additional information.

There are too many variables to just look at the line and say "ah hah". If possible can you please give me some information that might help in reproducing the issue?

[galuszkak]

@fxdgear so the problem is that this happens randomly from time to time. I will try to nail it scenario that I can reproduce that but it may take time.

[manjiler]

@fxdgear
I could hit this issue.
Setup details
library version - elasticsearch==5.5.1, elasticsearch-dsl==5.3.0
ES version - 6.1.4 (I know that I should use 6.x version of library but I am not using any features of 6.x)

The ES index has around 10,00,000 documents where each document has roughly around 2000 fields.
So the size of documents would clearly exceed 64k which the max limit for https://github.com/python/cpython/blob/3.6/Lib/http/client.py - _MAXLINE = 65536

Can you also let me know how to enable logging in elasticsearch-py so that I can root this more accurately?

Exception
GET http://localhost:9200/ultron/sr-perform/_search [status:N/A request:3.974s]
Traceback (most recent call last):
File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 600, in urlopen
chunked=chunked)
File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 386, in _make_request
six.raise_from(e, None)
File "", line 2, in raise_from
File "/Users/srGET http://localhost:9200/ultron/sr-perform/_search [status:N/A request:3.924s]
Traceback (most recent call last):
File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 600, in urlopen
chunked=chunked)
File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 386, in _make_request
six.raise_from(e, None)
File "", line 2, in raise_from
File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 382, in _make_request
httplib_response = conn.getresponse()
File "/Users/srivatsm/anaconda3/lib/python3.6/http/client.py", line 1331, in getresponse
response.begin()
File "/Users/srivatsm/anaconda3/lib/python3.6/http/client.py", line 297, in begin
version, status, reason = self._read_status()
File "/Users/srivatsm/anaconda3/lib/python3.6/http/client.py", line 260, in _read_status
raise LineTooLGET http://localhost:9200/ultron/sr-perform/_search [status:N/A request:3.933s]
Traceback (most recent call last):
File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 600, in urlopen
chunked=chunked)
File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 386, in _make_request
six.raise_from(e, None)
File "", line 2, in raise_from
File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 382, in _make_request
httplib_response = conn.getresponse()
File "/Users/srivatsm/anaconda3/lib/python3.6/http/client.py", line 1331, in getresponse
response.begin()
File "/Users/srivatsm/anaconda3/lib/python3.6/http/client.py", line 297, in begin
version, status, reason = self._read_status()
File "/Users/srivatsm/anaconda3/lib/python3.6/http/client.py", line 260, in _read_status
raise LineTooLong("status line")
http.client.LineTooLong: got more than 65536 bytes when reading status line

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/requests/adapters.py", line 440, in send
    timeout=timeout
  File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 649, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/util/retry.py", line 357, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/packages/six.py", line 685, in reraise
    raise value.with_traceback(tb)
  File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 600, in urlopen
    chunked=chunked)
  File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 386, in _make_request
    six.raise_from(e, None)
  File "<string>", line 2, in raise_from
  File "/Users/srivatsm/Projects/Ultron/vibranium/venv/lib/python3.6/site-packages/urllib3/connectionpool.py", line 382, in _make_request
    httplib_response = conn.getresponse()
  File "/Users/srivatsm/anaconda3/lib/python3.6/http/client.py", line 1331, in getresponse
    response.begin()
  File "/Users/srivatsm/anaconda3/lib/python3.6/http/client.py", line 297, in begin
    version, status, reason = self._read_status()
  File "/Users/srivatsm/anaconda3/lib/python3.6/http/client.py", line 260, in _read_status
    raise LineTooLong("status line")
urllib3.exceptions.ProtocolError: ('Connection aborted.', LineTooLong('got more than 65536 bytes when reading status line',))

Is there any work around this?

[manjiler]

@fxdgear How to enable chunked response with Urllib3HttpConnection or RequestsHttpConnection?

[fxdgear]

@manjiler To enable chunking you'd have to create your own connection class by extending Urllib3HttpConnection. Please see this comment on how to do that.

[fxdgear]

Can you also let me know how to enable logging in elasticsearch-py so that I can root this more accurately?

Logging is enabled by default. I'm not sure what you're asking here. What are you trying to log?

[manjiler]

@fxdgear I need to look at elasticsearch-py logs when I make calls using the library.

[manjiler]

@fxdgear Can you have a look at the exception that I have pasted?. I need to retrieve a document that can be over 64k in size.

[fxdgear]

@manjiler elasticsearch-py has two loggers configured:

1. elasticsearch which logs standard activity
2. elasticsearch.trace which logs connections to server in the form of curl commands.

for more info please see: http://elasticsearch-py.readthedocs.io/en/master/#logging

[fxdgear]

@manjiler

You asked earlier about enabling chunking to get large response objects back. In order to do that, you would have to create your own connection class. Chunked responses are disabled by default. But this library was written with the option to define your own connection classes to do what ever things you want to do.

To create your own connection class that enables chunking

class MyConnectionClasss(Urllib3HttpConnection):
    def perform_request(self, method, url, params=None, body=None, timeout=None, ignore=(), headers=None):

        ...
        # override this line: https://github.com/elastic/elasticsearch-py/blob/4dc4ba18ad08eb112d086f9a21aa44506e52f1de/elasticsearch/connection/http_urllib3.py#L165
        response = self.pool.urlopen(method, url, body, retries=False, headers=request_headers, chunked=True)
        ...

[manjiler]

@fxdgear Thanks for the same. I will do that.
I am using the library from a flask app, in this context where would I find the log files?

[fxdgear]

Tbh I’m not sure. :(

I’ve not used flask before. My background is Django, and as such the paradigms are quite different.

Maybe there’s a logging util in flask that can expose various loggers. And you can specify the elasticsearch loggers in the flask logger?

This way flask will bubble up other loggers.

I know that’s how it works in Django.

I hope that helps.

[manjiler]

@fxdgear I was able to add elasticsearch loggers to flask logger.
I figured out my problem, thanks to the note the on docs https://elasticsearch-py.readthedocs.io/en/master/
I was spawning multiple process in background and each of them were using the same instance of Elasticsearch() which caused data to get messed up between different calls.
Now I have a separate instance of Elasticsearch() for each process.

Thanks for your time 👍