Reduce logging of errors inside IOStream (especially SSLError).

Coroutine-style usage converts most errors into StreamClosedErrors,
which are logged less noisily while still allowing the original error
to be seen via the new real_error attribute. SSL errors now typically
result in a single log line instead of a full stack trace.

Closes #1304.

diff --git a/tornado/iostream.py b/tornado/iostream.py
index 3a175a679671ad4feb545e7471da2e4622e77a34..e17786ae1010fa0df6b8218bcce6ad74f9661acf 100644 (file)
--- a/tornado/iostream.py
+++ b/tornado/iostream.py
@@ -89,8 +89,16 @@ class StreamClosedError(IOError):
     Note that the close callback is scheduled to run *after* other
     callbacks on the stream (to allow for buffered data to be processed),
     so you may see this error before you see the close callback.
+
+    The ``real_error`` attribute contains the underlying error that caused
+    the stream to close (if any).
+
+    .. versionchanged:: 4.3
+       Added the ``real_error`` attribute.
     """
-    pass
+    def __init__(self, real_error=None):
+        super(StreamClosedError, self).__init__('Stream is closed')
+        self.real_error = real_error
 
 
 class UnsatisfiableReadError(Exception):
@@ -446,13 +454,7 @@ class BaseIOStream(object):
                 futures.append(self._ssl_connect_future)
                 self._ssl_connect_future = None
             for future in futures:
-                if self._is_connreset(self.error):
-                    # Treat connection resets as closed connections so
-                    # clients only have to catch one kind of exception
-                    # to avoid logging.
-                    future.set_exception(StreamClosedError())
-                else:
-                    future.set_exception(self.error or StreamClosedError())
+                future.set_exception(StreamClosedError(real_error=self.error))
             if self._close_callback is not None:
                 cb = self._close_callback
                 self._close_callback = None
@@ -644,8 +646,8 @@ class BaseIOStream(object):
             pos = self._read_to_buffer_loop()
         except UnsatisfiableReadError:
             raise
-        except Exception:
-            gen_log.warning("error on read", exc_info=True)
+        except Exception as e:
+            gen_log.warning("error on read: %s" % e)
             self.close(exc_info=True)
             return
         if pos is not None:
@@ -875,7 +877,7 @@ class BaseIOStream(object):
 
     def _check_closed(self):
         if self.closed():
-            raise StreamClosedError("Stream is closed")
+            raise StreamClosedError(real_error=self.error)
 
     def _maybe_add_error_listener(self):
         # This method is part of an optimization: to detect a connection that
@@ -1148,6 +1150,15 @@ class IOStream(BaseIOStream):
 
         def close_callback():
             if not future.done():
+                # Note that unlike most Futures returned by IOStream,
+                # this one passes the underlying error through directly
+                # instead of wrapping everything in a StreamClosedError
+                # with a real_error attribute. This is because once the
+                # connection is established it's more helpful to raise
+                # the SSLError directly than to hide it behind a
+                # StreamClosedError (and the client is expecting SSL
+                # issues rather than network issues since this method is
+                # named start_tls).
                 future.set_exception(ssl_stream.error or StreamClosedError())
             if orig_close_callback is not None:
                 orig_close_callback()
@@ -1311,8 +1322,8 @@ class SSLIOStream(IOStream):
             return False
         try:
             ssl_match_hostname(peercert, self._server_hostname)
-        except SSLCertificateError:
-            gen_log.warning("Invalid SSL certificate", exc_info=True)
+        except SSLCertificateError as e:
+            gen_log.warning("Invalid SSL certificate: %s" % e)
             return False
         else:
             return True

diff --git a/tornado/simple_httpclient.py b/tornado/simple_httpclient.py
index cf58e16263bc98fd1b9802845e295f15c17b440e..81ed887390e1de80053f756345b70b9db01c2ab4 100644 (file)
--- a/tornado/simple_httpclient.py
+++ b/tornado/simple_httpclient.py
@@ -427,7 +427,10 @@ class _HTTPConnection(httputil.HTTPMessageDelegate):
         if self.final_callback:
             self._remove_timeout()
             if isinstance(value, StreamClosedError):
-                value = HTTPError(599, "Stream closed")
+                if value.real_error is None:
+                    value = HTTPError(599, "Stream closed")
+                else:
+                    value = value.real_error
             self._run_callback(HTTPResponse(self.request, 599, error=value,
                                             request_time=self.io_loop.time() - self.start_time,
                                             ))

diff --git a/tornado/test/httpserver_test.py b/tornado/test/httpserver_test.py
index f05599dd12fe508a281f65daa0dbeb19ec4f4fb9..b445032afc8285c8d194c3b70446387a8aa02ccf 100644 (file)
--- a/tornado/test/httpserver_test.py
+++ b/tornado/test/httpserver_test.py
@@ -117,6 +117,16 @@ class SSLTestMixin(object):
                 response = self.wait()
         self.assertEqual(response.code, 599)
 
+    def test_error_logging(self):
+        # No stack traces are logged for SSL errors.
+        with ExpectLog(gen_log, 'SSL Error') as expect_log:
+            self.http_client.fetch(
+                self.get_url("/").replace("https:", "http:"),
+                self.stop)
+            response = self.wait()
+            self.assertEqual(response.code, 599)
+        self.assertFalse(expect_log.logged_stack)
+
 # Python's SSL implementation differs significantly between versions.
 # For example, SSLv3 and TLSv1 throw an exception if you try to read
 # from the socket before the handshake is complete, but the default

diff --git a/tornado/test/iostream_test.py b/tornado/test/iostream_test.py
index 933d68c0d1ee90c483982aadc40ea412dfe46dc2..4df83e38a10117b1176212822e60d97e65756f1f 100644 (file)
--- a/tornado/test/iostream_test.py
+++ b/tornado/test/iostream_test.py
@@ -940,7 +940,7 @@ class TestIOStreamStartTLS(AsyncTestCase):
         with ExpectLog(gen_log, "SSL Error"):
             with self.assertRaises(ssl.SSLError):
                 yield client_future
-        with self.assertRaises((ssl.SSLError, socket.error)):
+        with self.assertRaises(ssl.SSLError):
             yield server_future
 
 

diff --git a/tornado/test/simple_httpclient_test.py b/tornado/test/simple_httpclient_test.py
index c0de22b7cf08cdc186ad0c0b57c99e7186f541cf..b301c7e6efd87906d0aa9768c326fd7942608519 100644 (file)
--- a/tornado/test/simple_httpclient_test.py
+++ b/tornado/test/simple_httpclient_test.py
@@ -463,6 +463,16 @@ class SimpleHTTPSClientTestCase(SimpleHTTPClientTestMixin, AsyncHTTPSTestCase):
             resp = self.fetch("/hello", ssl_options=ctx)
         self.assertRaises(ssl.SSLError, resp.rethrow)
 
+    def test_error_logging(self):
+        # No stack traces are logged for SSL errors (in this case,
+        # failure to validate the testing self-signed cert).
+        # The SSLError is exposed through ssl.SSLError.
+        with ExpectLog(gen_log, '.*') as expect_log:
+            response = self.fetch("/", validate_cert=True)
+            self.assertEqual(response.code, 599)
+            self.assertIsInstance(response.error, ssl.SSLError)
+        self.assertFalse(expect_log.logged_stack)
+
 
 class CreateAsyncHTTPClientTestCase(AsyncTestCase):
     def setUp(self):

diff --git a/tornado/testing.py b/tornado/testing.py
index 517e50994c04d7034f722017a32290781e6523f9..f3cfb77355d64f00cedd3455afd701bee6c43291 100644 (file)
--- a/tornado/testing.py
+++ b/tornado/testing.py
@@ -589,10 +589,16 @@ class ExpectLog(logging.Filter):
     Useful to make tests of error conditions less noisy, while still
     leaving unexpected log entries visible.  *Not thread safe.*
 
+    The attribute ``logged_stack`` is set to true if any exception
+    stack trace was logged.
+
     Usage::
 
         with ExpectLog('tornado.application', "Uncaught exception"):
             error_response = self.fetch("/some_page")
+
+    .. versionchanged:: 4.3
+       Added the ``logged_stack`` attribute.
     """
     def __init__(self, logger, regex, required=True):
         """Constructs an ExpectLog context manager.
@@ -610,8 +616,11 @@ class ExpectLog(logging.Filter):
         self.regex = re.compile(regex)
         self.required = required
         self.matched = False
+        self.logged_stack = False
 
     def filter(self, record):
+        if record.exc_info:
+            self.logged_stack = True
         message = record.getMessage()
         if self.regex.match(message):
             self.matched = True
@@ -620,6 +629,7 @@ class ExpectLog(logging.Filter):
 
     def __enter__(self):
         self.logger.addFilter(self)
+        return self
 
     def __exit__(self, typ, value, tb):
         self.logger.removeFilter(self)