TLS-enabled server logs spurious errors on TCP connections

[davidblewett]

We are terminating TLS in Tornado so that we can do client certificate validation. Tornado is then proxied to via an AWS ELB that is doing TCP-level health checks of the service. Because these connections do not complete the handshake, I see a lot of logs like this:

dragnet-56f746f99b-v9c8n dragnet 2018-09-19 14:13:13,497 1 ERROR   [asyncio:1591] Exception in callback None()                               
dragnet-56f746f99b-v9c8n dragnet handle: <Handle cancelled>                                                                              
dragnet-56f746f99b-v9c8n dragnet Traceback (most recent call last):                                                                       
dragnet-56f746f99b-v9c8n dragnet   File "/usr/local/lib/python3.7/asyncio/events.py", line 88, in _run                                                                                                                                                               
dragnet-56f746f99b-v9c8n dragnet     self._context.run(self._callback, *self._args)                                                  
dragnet-56f746f99b-v9c8n dragnet   File "/usr/local/lib/python3.7/site-packages/tornado/platform/asyncio.py", line 122, in _handle_events
dragnet-56f746f99b-v9c8n dragnet     handler_func(fileobj, events)                                                                        
dragnet-56f746f99b-v9c8n dragnet   File "/usr/local/lib/python3.7/site-packages/tornado/stack_context.py", line 300, in null_wrapper
dragnet-56f746f99b-v9c8n dragnet     return fn(*args, **kwargs)                                                                           
dragnet-56f746f99b-v9c8n dragnet   File "/usr/local/lib/python3.7/site-packages/tornado/iostream.py", line 709, in _handle_events    
dragnet-56f746f99b-v9c8n dragnet     self._handle_read()                                                                                 
dragnet-56f746f99b-v9c8n dragnet   File "/usr/local/lib/python3.7/site-packages/tornado/iostream.py", line 1581, in _handle_read          
dragnet-56f746f99b-v9c8n dragnet     self._do_ssl_handshake()                                                                        
dragnet-56f746f99b-v9c8n dragnet   File "/usr/local/lib/python3.7/site-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake    
dragnet-56f746f99b-v9c8n dragnet     self.socket.do_handshake()                                                                        
dragnet-56f746f99b-v9c8n dragnet   File "/usr/local/lib/python3.7/ssl.py", line 1108, in do_handshake                                    
dragnet-56f746f99b-v9c8n dragnet     self._sslobj.do_handshake()                                                                     
dragnet-56f746f99b-v9c8n dragnet OSError: [Errno 0] Error

I've tested on Python 3.7 and Python 3.6, Tornado 5.1.

Simple test case:

import ssl
import tornado.web
ssl_ctx = ssl.create_default_context()
ssl_ctx.check_hostname = False
app = tornado.web.Application()
app.listen(8888, ssl_options=ssl_ctx)
tornado.ioloop.IOLoop.current().start()

Then sleep 0.1 | telnet 127.0.0.1 8888 or nc -vz 127.0.0.1 8888 (btw, the check_hostname is to prevent this traceback; not sure how to set server_hostname correctly in this context):

ERROR:asyncio:Exception in callback BaseAsyncIOLoop._handle_events(12, 1)
handle: <Handle BaseAsyncIOLoop._handle_events(12, 1)>
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/events.py", line 145, in _run
    self._callback(*self._args)
  File "/home/dblewett/.virtualenvs/dragnet-0UOjSQS6/lib/python3.6/site-packages/tornado/platform/asyncio.py", line 122, in _handle_events
    handler_func(fileobj, events)
  File "/home/dblewett/.virtualenvs/dragnet-0UOjSQS6/lib/python3.6/site-packages/tornado/stack_context.py", line 300, in null_wrapper
    return fn(*args, **kwargs)
  File "/home/dblewett/.virtualenvs/dragnet-0UOjSQS6/lib/python3.6/site-packages/tornado/netutil.py", line 262, in accept_handler
    callback(connection, address)
  File "/home/dblewett/.virtualenvs/dragnet-0UOjSQS6/lib/python3.6/site-packages/tornado/tcpserver.py", line 263, in _handle_connection
    do_handshake_on_connect=False)
  File "/home/dblewett/.virtualenvs/dragnet-0UOjSQS6/lib/python3.6/site-packages/tornado/netutil.py", line 573, in ssl_wrap_socket
    **kwargs)
  File "/usr/lib/python3.6/ssl.py", line 407, in wrap_socket
    _context=self, _session=session)
  File "/usr/lib/python3.6/ssl.py", line 770, in __init__
    raise ValueError("check_hostname requires server_hostname")
ValueError: check_hostname requires server_hostname

[davidblewett]

Is there some way we can catch and ignore these?

[bdarnell]

Looks like it's time to add another case to the big try/except block here:

tornado/tornado/iostream.py

Lines 1321 to 1353 in 627eafb

	except ssl.SSLError as err:
	if err.args[0] == ssl.SSL_ERROR_WANT_READ:
	self._handshake_reading = True
	return
	elif err.args[0] == ssl.SSL_ERROR_WANT_WRITE:
	self._handshake_writing = True
	return
	elif err.args[0] in (ssl.SSL_ERROR_EOF,
	ssl.SSL_ERROR_ZERO_RETURN):
	return self.close(exc_info=err)
	elif err.args[0] == ssl.SSL_ERROR_SSL:
	try:
	peer = self.socket.getpeername()
	except Exception:
	peer = '(not connected)'
	gen_log.warning("SSL Error on %s %s: %s",
	self.socket.fileno(), peer, err)
	return self.close(exc_info=err)
	raise
	except socket.error as err:
	# Some port scans (e.g. nmap in -sT mode) have been known
	# to cause do_handshake to raise EBADF and ENOTCONN, so make
	# those errors quiet as well.
	# https://groups.google.com/forum/?fromgroups#!topic/python-tornado/ApucKJat1_0
	if (self._is_connreset(err) or
	err.args[0] in (errno.EBADF, errno.ENOTCONN)):
	return self.close(exc_info=err)
	raise
	except AttributeError as err:
	# On Linux, if the connection was reset before the call to
	# wrap_socket, do_handshake will fail with an
	# AttributeError.
	return self.close(exc_info=err)

This TCP-level healthcheck is supposed to turn into either SSL_ERROR_EOF (if the connection was shut down cleanly) or a socket.error matching _is_connreset (if it's not. Note that socket.error is an alias for OSError in python 3). When I try the nc command above I get SSL_ERROR_EOF, so I can't reproduce the backtrace you're seeing (python 3.7 on a mac).

Errno 0 looks like a bug; I don't know if it's a good idea to catch that and silence it. It sounds like you might be running into https://bugs.python.org/issue31122

not sure how to set server_hostname correctly in this context

This is because ssl.create_default_context() with no arguments creates a client-side context, which requires that you either provide the hostname of the server you're connecting to or explicitly disable this check. You need a server-side context (created by ssl.create_default_context(ssl.Purpose.CLIENT_AUTH), and you'll probably need to load a certificate for it to actually work).

[davidblewett]

@bdarnell I created a simple docker test harness: https://gist.github.com/davidblewett/1d9ad0f09274ad4adf8d7b6c403622ac .

docker build . -t tornado_test && docker run --rm tornado_test python /app/test.py
Sending build context to Docker daemon  3.072kB
Step 1/4 : FROM python:3.7
 ---> a9d071760c82
Step 2/4 : RUN mkdir /app
 ---> Using cache
 ---> ddb39ed76e3f
Step 3/4 : COPY . /app
 ---> d3c6491038c8
Step 4/4 : RUN apt-get update &&     apt-get install -y netcat &&     pip install Tornado
 ---> Running in c2ce170d313d
Get:1 http://security.debian.org/debian-security stretch/updates InRelease [94.3 kB]
Ign:2 http://deb.debian.org/debian stretch InRelease
Get:3 http://deb.debian.org/debian stretch-updates InRelease [91.0 kB]
Get:4 http://security.debian.org/debian-security stretch/updates/main amd64 Packages [447 kB]
Get:5 http://deb.debian.org/debian stretch Release [118 kB]
Get:6 http://deb.debian.org/debian stretch-updates/main amd64 Packages [5148 B]
Get:7 http://deb.debian.org/debian stretch Release.gpg [2434 B]
Get:8 http://deb.debian.org/debian stretch/main amd64 Packages [7099 kB]
Fetched 7856 kB in 7s (1068 kB/s)
Reading package lists...
Reading package lists...
Building dependency tree...
Reading state information...
The following additional packages will be installed:
  netcat-traditional
The following NEW packages will be installed:
  netcat netcat-traditional
0 upgraded, 2 newly installed, 0 to remove and 13 not upgraded.
Need to get 76.0 kB of archives.
After this operation, 173 kB of additional disk space will be used.
Get:1 http://deb.debian.org/debian stretch/main amd64 netcat-traditional amd64 1.10-41+b1 [67.0 kB]
Get:2 http://deb.debian.org/debian stretch/main amd64 netcat all 1.10-41 [8962 B]
debconf: delaying package configuration, since apt-utils is not installed
Fetched 76.0 kB in 0s (84.6 kB/s)
Selecting previously unselected package netcat-traditional.
(Reading database ... 30245 files and directories currently installed.)
Preparing to unpack .../netcat-traditional_1.10-41+b1_amd64.deb ...
Unpacking netcat-traditional (1.10-41+b1) ...
Selecting previously unselected package netcat.
Preparing to unpack .../netcat_1.10-41_all.deb ...
Unpacking netcat (1.10-41) ...
Setting up netcat-traditional (1.10-41+b1) ...
update-alternatives: using /bin/nc.traditional to provide /bin/nc (nc) in auto mode
Setting up netcat (1.10-41) ...
Collecting Tornado
  Downloading https://files.pythonhosted.org/packages/e6/78/6e7b5af12c12bdf38ca9bfe863fcaf53dc10430a312d0324e76c1e5ca426/tornado-5.1.1.tar.gz (516kB)
Building wheels for collected packages: Tornado
  Running setup.py bdist_wheel for Tornado: started
  Running setup.py bdist_wheel for Tornado: finished with status 'done'
  Stored in directory: /root/.cache/pip/wheels/6d/e1/ce/f4ee2fa420cc6b940123c64992b81047816d0a9fad6b879325
Successfully built Tornado
Installing collected packages: Tornado
Successfully installed Tornado-5.1.1
Removing intermediate container c2ce170d313d
 ---> a12097802e9d
Successfully built a12097802e9d
Successfully tagged tornado_test:latest
localhost [127.0.0.1] 8888 (?) open
ERROR:tornado.general:Uncaught exception, closing connection.
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/tornado/iostream.py", line 709, in _handle_events
    self._handle_read()
  File "/usr/local/lib/python3.7/site-packages/tornado/iostream.py", line 1581, in _handle_read
    self._do_ssl_handshake()
  File "/usr/local/lib/python3.7/site-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake
    self.socket.do_handshake()
  File "/usr/local/lib/python3.7/ssl.py", line 1108, in do_handshake
    self._sslobj.do_handshake()
OSError: [Errno 0] Error
ERROR:asyncio:Exception in callback None()
handle: <Handle cancelled>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.7/site-packages/tornado/platform/asyncio.py", line 122, in _handle_events
    handler_func(fileobj, events)
  File "/usr/local/lib/python3.7/site-packages/tornado/stack_context.py", line 300, in null_wrapper
    return fn(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/tornado/iostream.py", line 709, in _handle_events
    self._handle_read()
  File "/usr/local/lib/python3.7/site-packages/tornado/iostream.py", line 1581, in _handle_read
    self._do_ssl_handshake()
  File "/usr/local/lib/python3.7/site-packages/tornado/iostream.py", line 1501, in _do_ssl_handshake
    self.socket.do_handshake()
  File "/usr/local/lib/python3.7/ssl.py", line 1108, in do_handshake
    self._sslobj.do_handshake()
OSError: [Errno 0] Error

[bdarnell]

Thanks for the reproduction script. I don't see any way around it, so I've added "errno 0" to the list of silent errors here in #2518.