http1connection: Improve error logging for invalid host headers

This was previously being logged as an uncaught exception in application
code, which is wrong for a malformed request. HTTPInputError now passes
through the app-error logging to be caught and reported as a 400
(which logs at the warning level to the access log and info to the
general log).

Fixes #3510

diff --git a/tornado/http1connection.py b/tornado/http1connection.py
index 8dd0c9b6e27d5faab1456fcf466803c03b26c712..5b0dd1b8d06e2709e1971612d1d81f1d304ee13c 100644 (file)
--- a/tornado/http1connection.py
+++ b/tornado/http1connection.py
@@ -66,6 +66,9 @@ class _ExceptionLoggingContext:
     ) -> None:
         if value is not None:
             assert typ is not None
+            # Let HTTPInputError pass through to higher-level handler
+            if isinstance(value, httputil.HTTPInputError):
+                return None
             self.logger.error("Uncaught exception", exc_info=(typ, value, tb))
             raise _QuietException
 

diff --git a/tornado/routing.py b/tornado/routing.py
index 245070c797c333d9eb859996c3a4f05849c4c73d..ff833d5e7463693ad81a5bc4fef053708ab5afad 100644 (file)
--- a/tornado/routing.py
+++ b/tornado/routing.py
@@ -279,8 +279,8 @@ class _RoutingDelegate(httputil.HTTPMessageDelegate):
         self.delegate.finish()
 
     def on_connection_close(self) -> None:
-        assert self.delegate is not None
-        self.delegate.on_connection_close()
+        if self.delegate is not None:
+            self.delegate.on_connection_close()
 
 
 class _DefaultMessageDelegate(httputil.HTTPMessageDelegate):

diff --git a/tornado/test/httpclient_test.py b/tornado/test/httpclient_test.py
index 08c809a2fcd192b7b7814bb3ae3a4f24f9781fe0..77c0d6eb9bfb204c1580509b57238a655cab08da 100644 (file)
--- a/tornado/test/httpclient_test.py
+++ b/tornado/test/httpclient_test.py
@@ -442,7 +442,7 @@ Transfer-Encoding: chunked
         # test if client hangs on tricky invalid gzip
         # curl/simple httpclient have different behavior (exception, logging)
         with ExpectLog(
-            app_log, "(Uncaught exception|Exception in callback)", required=False
+            gen_log, ".*Malformed HTTP message.*unconsumed gzip data", required=False
         ):
             try:
                 response = self.fetch("/invalid_gzip")

diff --git a/tornado/test/httpserver_test.py b/tornado/test/httpserver_test.py
index f197cfef8466bde418b0e9544b94af93c0c13680..008078ed9794e2e7ba91fafb717a1de9f3ad0e66 100644 (file)
--- a/tornado/test/httpserver_test.py
+++ b/tornado/test/httpserver_test.py
@@ -462,6 +462,18 @@ class HTTPServerRawTest(AsyncHTTPTestCase):
             self.io_loop.add_timeout(datetime.timedelta(seconds=0.05), self.stop)
             self.wait()
 
+    def test_invalid_host_header_with_whitespace(self):
+        with ExpectLog(
+            gen_log, ".*Malformed HTTP message.*Invalid Host header", level=logging.INFO
+        ):
+            self.stream.write(b"GET / HTTP/1.0\r\nHost: foo bar\r\n\r\n")
+            start_line, headers, response = self.io_loop.run_sync(
+                lambda: read_stream_body(self.stream)
+            )
+            self.assertEqual("HTTP/1.1", start_line.version)
+            self.assertEqual(400, start_line.code)
+            self.assertEqual("Bad Request", start_line.reason)
+
     def test_chunked_request_body(self):
         # Chunked requests are not widely supported and we don't have a way
         # to generate them in AsyncHTTPClient, but HTTPServer will read them.