From: Ben Darnell Date: Sun, 5 Jul 2015 02:40:23 +0000 (-0400) Subject: Reduce logging of errors inside IOStream (especially SSLError). X-Git-Tag: v4.3.0b1~83 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=d74d58384bc7b123235da95ec6580799c384a7ad;p=thirdparty%2Ftornado.git 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 3a175a679..e17786ae1 100644 --- 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 cf58e1626..81ed88739 100644 --- 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 f05599dd1..b445032af 100644 --- 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 933d68c0d..4df83e38a 100644 --- 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 c0de22b7c..b301c7e6e 100644 --- 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 517e50994..f3cfb7735 100644 --- 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)