TLS-enabled server logs spurious errors on TCP connections

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

Is there some way we can catch and ignore these?

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).

@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

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.

	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)