Elasticsearch-py: Connection timeout uncatchable traceback

[pdonorio]

Hello there,

I am plugging elasticsearch as a service inside my Flask application.
I created an automatic connection checker at Flask server startup to see if all the databases are available before serving any request.

The check is inside a try ... except, it took me some time with elasticsearch on Python.
I think a very confusing problem is the fact that despite the exception catching many traceback are printed from socket, urllib and http requests.

To easily show what I mean we could test a simple code like:

from elasticsearch import Elasticsearch

es = Elasticsearch([{'host': 'doesnotexist'}], timeout=2)
try:
    es.ping()
    print("connected")
except:
    print("failed")

which executed prints:

HEAD http://doesnotexist:9200/ [status:N/A request:0.917s]
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 142, in _new_conn
    (self.host, self.port), self.timeout, **extra_kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/connection.py", line 75, in create_connection
    for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):
  File "/usr/lib/python3.5/socket.py", line 732, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -2] Name or service not known

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/elasticsearch/connection/http_urllib3.py", line 94, in perform_request
    response = self.pool.urlopen(method, url, body, retries=False, headers=self.headers, **kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 640, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/retry.py", line 238, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/packages/six.py", line 686, in reraise
    raise value
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 595, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 363, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/lib/python3.5/http/client.py", line 1106, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib/python3.5/http/client.py", line 1151, in _send_request
    self.endheaders(body)
  File "/usr/lib/python3.5/http/client.py", line 1102, in endheaders
    self._send_output(message_body)
  File "/usr/lib/python3.5/http/client.py", line 934, in _send_output
    self.send(msg)
  File "/usr/lib/python3.5/http/client.py", line 877, in send
    self.connect()
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 167, in connect
    conn = self._new_conn()
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 151, in _new_conn
    self, "Failed to establish a new connection: %s" % e)
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPConnection object at 0x7f79dddcc278>: Failed to establish a new connection: [Errno -2] Name or service not known
HEAD http://doesnotexist:9200/ [status:N/A request:0.131s]
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 142, in _new_conn
    (self.host, self.port), self.timeout, **extra_kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/connection.py", line 75, in create_connection
    for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):
  File "/usr/lib/python3.5/socket.py", line 732, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -2] Name or service not known

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/elasticsearch/connection/http_urllib3.py", line 94, in perform_request
    response = self.pool.urlopen(method, url, body, retries=False, headers=self.headers, **kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 640, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/retry.py", line 238, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/packages/six.py", line 686, in reraise
    raise value
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 595, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 363, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/lib/python3.5/http/client.py", line 1106, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib/python3.5/http/client.py", line 1151, in _send_request
    self.endheaders(body)
  File "/usr/lib/python3.5/http/client.py", line 1102, in endheaders
    self._send_output(message_body)
  File "/usr/lib/python3.5/http/client.py", line 934, in _send_output
    self.send(msg)
  File "/usr/lib/python3.5/http/client.py", line 877, in send
    self.connect()
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 167, in connect
    conn = self._new_conn()
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 151, in _new_conn
    self, "Failed to establish a new connection: %s" % e)
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPConnection object at 0x7f79dddcc390>: Failed to establish a new connection: [Errno -2] Name or service not known
HEAD http://doesnotexist:9200/ [status:N/A request:0.162s]
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 142, in _new_conn
    (self.host, self.port), self.timeout, **extra_kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/connection.py", line 75, in create_connection
    for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):
  File "/usr/lib/python3.5/socket.py", line 732, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -2] Name or service not known

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/elasticsearch/connection/http_urllib3.py", line 94, in perform_request
    response = self.pool.urlopen(method, url, body, retries=False, headers=self.headers, **kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 640, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/retry.py", line 238, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/packages/six.py", line 686, in reraise
    raise value
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 595, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 363, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/lib/python3.5/http/client.py", line 1106, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib/python3.5/http/client.py", line 1151, in _send_request
    self.endheaders(body)
  File "/usr/lib/python3.5/http/client.py", line 1102, in endheaders
    self._send_output(message_body)
  File "/usr/lib/python3.5/http/client.py", line 934, in _send_output
    self.send(msg)
  File "/usr/lib/python3.5/http/client.py", line 877, in send
    self.connect()
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 167, in connect
    conn = self._new_conn()
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 151, in _new_conn
    self, "Failed to establish a new connection: %s" % e)
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPConnection object at 0x7f79ddddac18>: Failed to establish a new connection: [Errno -2] Name or service not known
HEAD http://doesnotexist:9200/ [status:N/A request:0.136s]
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 142, in _new_conn
    (self.host, self.port), self.timeout, **extra_kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/connection.py", line 75, in create_connection
    for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):
  File "/usr/lib/python3.5/socket.py", line 732, in getaddrinfo
    for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -2] Name or service not known

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/elasticsearch/connection/http_urllib3.py", line 94, in perform_request
    response = self.pool.urlopen(method, url, body, retries=False, headers=self.headers, **kw)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 640, in urlopen
    _stacktrace=sys.exc_info()[2])
  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/retry.py", line 238, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/packages/six.py", line 686, in reraise
    raise value
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 595, in urlopen
    chunked=chunked)
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 363, in _make_request
    conn.request(method, url, **httplib_request_kw)
  File "/usr/lib/python3.5/http/client.py", line 1106, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib/python3.5/http/client.py", line 1151, in _send_request
    self.endheaders(body)
  File "/usr/lib/python3.5/http/client.py", line 1102, in endheaders
    self._send_output(message_body)
  File "/usr/lib/python3.5/http/client.py", line 934, in _send_output
    self.send(msg)
  File "/usr/lib/python3.5/http/client.py", line 877, in send
    self.connect()
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 167, in connect
    conn = self._new_conn()
  File "/usr/local/lib/python3.5/dist-packages/urllib3/connection.py", line 151, in _new_conn
    self, "Failed to establish a new connection: %s" % e)
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPConnection object at 0x7f79dd758780>: Failed to establish a new connection: [Errno -2] Name or service not known
failed

Can all of those errors be removed?

My versions:

$ python --version
Python 3.5.1+

$ pip freeze | grep -i elastic
elasticsearch==2.3.0
elasticsearch-dsl==2.1.0

Thanks

[pdonorio]

Also I just checked the latest master from git and you get the same error stack, but instead of ending with "failed", it prints "connected", very weird.

[HonzaKral]

This is caused just by logging - the exception is actually correctly caught and handled, but the default logging still prints the info on stderr. To suppress the printout, just set the logging to a higher level:

import logging
logging.basicConfig(level=logging.CRITICAL)

Hope this helps

[pdonorio]

Doesn't help much in my case, where I use the logger. I tried some tests and I can't just switch the log to that level only for that operation.

What I don't understand is why the whole traceback is logged if you raise the error again. Wouldn't be only the error string be enough? Shouldn't I handle the exception on my side where I receive the exception?

Or could you provide a parameter to suppress those logs?

[pdonorio]

Ok, I created a work around by selecting specific loggers to be silenced:

from elasticsearch import Elasticsearch
import logging

# My app logger
logger = logging.getLogger(__name__)
my_log_level = logging.DEBUG
logging.basicConfig(level=my_log_level)
logger.debug("Init app")

# print("Current loggers:", logging.Logger.manager.loggerDict.keys())

# Elasticsearch logger to be silenced
loggerES = logging.getLogger('elasticsearch')
loggerES.setLevel(logging.CRITICAL)
loggerUrlib = logging.getLogger('urllib3')
loggerUrlib.setLevel(logging.CRITICAL)

# Test a failing connection
es = Elasticsearch([{'host': 'doesnotexist'}], timeout=2)
try:
    es.ping()
    logger.info("Connected")
except:
    logger.info("Failed")

logger.debug("End of app")

Running the code:

$ python3 elasticonnection.py
DEBUG:__main__:Init app
INFO:__main__:Failed
DEBUG:__main__:End of app

I'm not entirely happy (I'd prefer not to add this extra code) but if you are not going to remove those logs that's still good enough.

Thanks

[HonzaKral]

Easier would be to provide a simple configuration via dictConfig: https://docs.python.org/3.5/howto/logging-cookbook.html#an-example-dictionary-based-configuration

That way you can store your configuration in a file and have it easily changed - without having to change code.

Note that this is not an issue of elasticsearch-py but in general of logging and libraries - even urllib3, the library we use for http, does it's own logging (such as is considered best practice).

[pdonorio]

Uh, thanks a lot for the dictConfig hint, I really like it!

even urllib3, the library we use for http, does it's own logging (such as is considered best practice)

Uhm, again, logging is a great thing, but absolutely not with printing the whole stacktrace on an exception, as you flood stdout with no reason. The error message from the exception would be enough.

And to prove it, I use the same connection-checking with redis, RethinkDB, neo4j, and postgresql:
none of them had this behavior. I encountered the first time in this case and that's why I didn't even realize the problem was logging at first.

[bsolomon1124]

While this issue is closed, I believe it would be prudent to add NullHandler for _all_ versions of Python, not just 2.7 thru 3.2 @HonzaKral.

Currently in __init__.py you have:

if (2, 7) <= sys.version_info < (3, 2):
    # On Python 2.7 and Python3 < 3.2, install no-op handler to silence
    # `No handlers could be found for logger "elasticsearch"` message per
    # <https://docs.python.org/2/howto/logging.html#configuring-logging-for-a-library>
    import logging
    logger = logging.getLogger('elasticsearch')
    logger.addHandler(logging.NullHandler())

The comment above is partially missing the purpose of NullHandler. A logger that is declared in a library (such as it is here) with no further configuration will log to sys.stderr, even if that's not what the end user wants.

You can see this in logging.__init__: A logger calls callHandlers() and, because it doesn't have any handlers by default, it gets bumped down to using lastResort, which is a handler for sys.stderr. That is why @pdonorio is getting a huge traceback that he does not want. You will see even that urllib3 does this, but the traceback is actually printed due to elasticsearch-py, not urllib3.

Here is a confirmation of that directly from the logging docs:

An instance of this handler could be added to the top-level logger of the logging namespace used by the library (if you want to prevent your library’s logged events being output to sys.stderr in the absence of logging configuration).