]> git.ipfire.org Git - thirdparty/tornado.git/commitdiff
testing: Add level argument to ExpectLog
authorBen Darnell <ben@bendarnell.com>
Sun, 19 Jan 2020 20:11:54 +0000 (15:11 -0500)
committerBen Darnell <ben@bendarnell.com>
Sun, 19 Jan 2020 22:07:16 +0000 (17:07 -0500)
This makes it possible for tests to be a little more precise, and also
makes them less dependent on exactly how the test is run (runtests.py
sets the logging level to info, but when running tests directly from
an editor it may use the default of warnings-only).

CI only runs the tests with runtests.py, so this might regress, but I'm
not building anything to prevent that yet (options include running the
tests differently in CI or making ExpectLog always use a fixed log
configuration instead of picking up the current one)

tornado/test/httpserver_test.py
tornado/test/iostream_test.py
tornado/test/simple_httpclient_test.py
tornado/testing.py

index 63052ba12becdf4748977a00f413059d0473f685..ed91a99ffcb74234239872cb9b77983003160411 100644 (file)
@@ -34,6 +34,7 @@ from tornado.web import Application, RequestHandler, stream_request_body
 from contextlib import closing
 import datetime
 import gzip
+import logging
 import os
 import shutil
 import socket
@@ -480,7 +481,7 @@ class HTTPServerRawTest(AsyncHTTPTestCase):
         self.wait()
 
     def test_malformed_first_line_response(self):
-        with ExpectLog(gen_log, ".*Malformed HTTP request line"):
+        with ExpectLog(gen_log, ".*Malformed HTTP request line", level=logging.INFO):
             self.stream.write(b"asdf\r\n\r\n")
             start_line, headers, response = self.io_loop.run_sync(
                 lambda: read_stream_body(self.stream)
@@ -490,7 +491,7 @@ class HTTPServerRawTest(AsyncHTTPTestCase):
             self.assertEqual("Bad Request", start_line.reason)
 
     def test_malformed_first_line_log(self):
-        with ExpectLog(gen_log, ".*Malformed HTTP request line"):
+        with ExpectLog(gen_log, ".*Malformed HTTP request line", level=logging.INFO):
             self.stream.write(b"asdf\r\n\r\n")
             # TODO: need an async version of ExpectLog so we don't need
             # hard-coded timeouts here.
@@ -498,7 +499,11 @@ class HTTPServerRawTest(AsyncHTTPTestCase):
             self.wait()
 
     def test_malformed_headers(self):
-        with ExpectLog(gen_log, ".*Malformed HTTP message.*no colon in header line"):
+        with ExpectLog(
+            gen_log,
+            ".*Malformed HTTP message.*no colon in header line",
+            level=logging.INFO,
+        ):
             self.stream.write(b"GET / HTTP/1.0\r\nasdf\r\n\r\n")
             self.io_loop.add_timeout(datetime.timedelta(seconds=0.05), self.stop)
             self.wait()
@@ -553,7 +558,9 @@ bar
 
     @gen_test
     def test_invalid_content_length(self):
-        with ExpectLog(gen_log, ".*Only integer Content-Length is allowed"):
+        with ExpectLog(
+            gen_log, ".*Only integer Content-Length is allowed", level=logging.INFO
+        ):
             self.stream.write(
                 b"""\
 POST /echo HTTP/1.1
@@ -1215,14 +1222,14 @@ class BodyLimitsTest(AsyncHTTPTestCase):
         self.assertEqual(response.body, b"4096")
 
     def test_large_body_buffered(self):
-        with ExpectLog(gen_log, ".*Content-Length too long"):
+        with ExpectLog(gen_log, ".*Content-Length too long", level=logging.INFO):
             response = self.fetch("/buffered", method="PUT", body=b"a" * 10240)
         self.assertEqual(response.code, 400)
 
     @unittest.skipIf(os.name == "nt", "flaky on windows")
     def test_large_body_buffered_chunked(self):
         # This test is flaky on windows for unknown reasons.
-        with ExpectLog(gen_log, ".*chunked body too large"):
+        with ExpectLog(gen_log, ".*chunked body too large", level=logging.INFO):
             response = self.fetch(
                 "/buffered",
                 method="PUT",
@@ -1231,13 +1238,13 @@ class BodyLimitsTest(AsyncHTTPTestCase):
         self.assertEqual(response.code, 400)
 
     def test_large_body_streaming(self):
-        with ExpectLog(gen_log, ".*Content-Length too long"):
+        with ExpectLog(gen_log, ".*Content-Length too long", level=logging.INFO):
             response = self.fetch("/streaming", method="PUT", body=b"a" * 10240)
         self.assertEqual(response.code, 400)
 
     @unittest.skipIf(os.name == "nt", "flaky on windows")
     def test_large_body_streaming_chunked(self):
-        with ExpectLog(gen_log, ".*chunked body too large"):
+        with ExpectLog(gen_log, ".*chunked body too large", level=logging.INFO):
             response = self.fetch(
                 "/streaming",
                 method="PUT",
@@ -1270,7 +1277,7 @@ class BodyLimitsTest(AsyncHTTPTestCase):
                 b"PUT /streaming?body_timeout=0.1 HTTP/1.0\r\n"
                 b"Content-Length: 42\r\n\r\n"
             )
-            with ExpectLog(gen_log, "Timeout reading body"):
+            with ExpectLog(gen_log, "Timeout reading body", level=logging.INFO):
                 response = yield stream.read_until_close()
             self.assertEqual(response, b"")
         finally:
@@ -1294,7 +1301,7 @@ class BodyLimitsTest(AsyncHTTPTestCase):
             stream.write(
                 b"PUT /streaming HTTP/1.1\r\n" b"Content-Length: 10240\r\n\r\n"
             )
-            with ExpectLog(gen_log, ".*Content-Length too long"):
+            with ExpectLog(gen_log, ".*Content-Length too long", level=logging.INFO):
                 data = yield stream.read_until_close()
             self.assertEqual(data, b"HTTP/1.1 400 Bad Request\r\n\r\n")
         finally:
index d9e2c666b9fe97731f27a9274239b3e85cfbcd6b..359269cac500907fdf25b27e308ef9597ea65df6 100644 (file)
@@ -25,6 +25,7 @@ from tornado.test.util import skipIfNonUnix, refusing_port, skipPypy3V58
 from tornado.web import RequestHandler, Application
 import errno
 import hashlib
+import logging
 import os
 import platform
 import random
@@ -366,7 +367,7 @@ class TestReadWriteMixin(object):
 
             # Not enough space, but we don't know it until all we can do is
             # log a warning and close the connection.
-            with ExpectLog(gen_log, "Unsatisfiable read"):
+            with ExpectLog(gen_log, "Unsatisfiable read", level=logging.INFO):
                 fut = rs.read_until(b"def", max_bytes=5)
                 ws.write(b"123456")
                 yield closed.wait()
@@ -385,7 +386,7 @@ class TestReadWriteMixin(object):
             # inline.  For consistency with the out-of-line case, we
             # do not raise the error synchronously.
             ws.write(b"123456")
-            with ExpectLog(gen_log, "Unsatisfiable read"):
+            with ExpectLog(gen_log, "Unsatisfiable read", level=logging.INFO):
                 with self.assertRaises(StreamClosedError):
                     yield rs.read_until(b"def", max_bytes=5)
             yield closed.wait()
@@ -403,7 +404,7 @@ class TestReadWriteMixin(object):
             # puts us over the limit, we fail the request because it was not
             # found within the limit.
             ws.write(b"abcdef")
-            with ExpectLog(gen_log, "Unsatisfiable read"):
+            with ExpectLog(gen_log, "Unsatisfiable read", level=logging.INFO):
                 rs.read_until(b"def", max_bytes=5)
                 yield closed.wait()
         finally:
@@ -430,7 +431,7 @@ class TestReadWriteMixin(object):
 
             # Not enough space, but we don't know it until all we can do is
             # log a warning and close the connection.
-            with ExpectLog(gen_log, "Unsatisfiable read"):
+            with ExpectLog(gen_log, "Unsatisfiable read", level=logging.INFO):
                 rs.read_until_regex(b"def", max_bytes=5)
                 ws.write(b"123456")
                 yield closed.wait()
@@ -449,7 +450,7 @@ class TestReadWriteMixin(object):
             # inline.  For consistency with the out-of-line case, we
             # do not raise the error synchronously.
             ws.write(b"123456")
-            with ExpectLog(gen_log, "Unsatisfiable read"):
+            with ExpectLog(gen_log, "Unsatisfiable read", level=logging.INFO):
                 rs.read_until_regex(b"def", max_bytes=5)
                 yield closed.wait()
         finally:
@@ -466,7 +467,7 @@ class TestReadWriteMixin(object):
             # puts us over the limit, we fail the request because it was not
             # found within the limit.
             ws.write(b"abcdef")
-            with ExpectLog(gen_log, "Unsatisfiable read"):
+            with ExpectLog(gen_log, "Unsatisfiable read", level=logging.INFO):
                 rs.read_until_regex(b"def", max_bytes=5)
                 yield closed.wait()
         finally:
index a883786dcfc627efb75cfd3ba75d08d2359a1080..0f2c252fe8d75fdd095809a69943b2577e859f75 100644 (file)
@@ -316,7 +316,9 @@ class SimpleHTTPClientTestMixin(object):
         response = self.fetch("/content_length?value=2,%202,2")
         self.assertEqual(response.body, b"ok")
 
-        with ExpectLog(gen_log, ".*Multiple unequal Content-Lengths"):
+        with ExpectLog(
+            gen_log, ".*Multiple unequal Content-Lengths", level=logging.INFO
+        ):
             with self.assertRaises(HTTPStreamClosedError):
                 self.fetch("/content_length?value=2,4", raise_error=True)
             with self.assertRaises(HTTPStreamClosedError):
@@ -657,7 +659,9 @@ class HTTP204NoContentTestCase(AsyncHTTPTestCase):
 
     def test_204_invalid_content_length(self):
         # 204 status with non-zero content length is malformed
-        with ExpectLog(gen_log, ".*Response with code 204 should not have body"):
+        with ExpectLog(
+            gen_log, ".*Response with code 204 should not have body", level=logging.INFO
+        ):
             with self.assertRaises(HTTPStreamClosedError):
                 self.fetch("/?error=1", raise_error=True)
                 if not self.http1:
@@ -768,7 +772,9 @@ class MaxBodySizeTest(AsyncHTTPTestCase):
 
     def test_large_body(self):
         with ExpectLog(
-            gen_log, "Malformed HTTP message from None: Content-Length too long"
+            gen_log,
+            "Malformed HTTP message from None: Content-Length too long",
+            level=logging.INFO,
         ):
             with self.assertRaises(HTTPStreamClosedError):
                 self.fetch("/large", raise_error=True)
@@ -815,6 +821,7 @@ class ChunkedWithContentLengthTest(AsyncHTTPTestCase):
                 "Malformed HTTP message from None: Response "
                 "with both Transfer-Encoding and Content-Length"
             ),
+            level=logging.INFO,
         ):
             with self.assertRaises(HTTPStreamClosedError):
                 self.fetch("/chunkwithcl", raise_error=True)
index da275cbcecf0ac258ba1fc62401c34617d86d07a..4bc83e462a71f5c3f2e488f05b0b4a0876761358 100644 (file)
@@ -657,6 +657,7 @@ class ExpectLog(logging.Filter):
         logger: Union[logging.Logger, basestring_type],
         regex: str,
         required: bool = True,
+        level: Optional[int] = None,
     ) -> None:
         """Constructs an ExpectLog context manager.
 
@@ -666,6 +667,15 @@ class ExpectLog(logging.Filter):
             the specified logger that match this regex will be suppressed.
         :param required: If true, an exception will be raised if the end of
             the ``with`` statement is reached without matching any log entries.
+        :param level: A constant from the ``logging`` module indicating the
+            expected log level. If this parameter is provided, only log messages
+            at this level will be considered to match. Additionally, the
+            supplied ``logger`` will have its level adjusted if necessary
+            (for the duration of the ``ExpectLog`` to enable the expected
+            message.
+
+        .. versionchanged:: 6.1
+           Added the ``level`` parameter.
         """
         if isinstance(logger, basestring_type):
             logger = logging.getLogger(logger)
@@ -674,17 +684,28 @@ class ExpectLog(logging.Filter):
         self.required = required
         self.matched = False
         self.logged_stack = False
+        self.level = level
+        self.orig_level = None  # type: Optional[int]
 
     def filter(self, record: logging.LogRecord) -> bool:
         if record.exc_info:
             self.logged_stack = True
         message = record.getMessage()
         if self.regex.match(message):
+            if self.level is not None and record.levelno != self.level:
+                app_log.warning(
+                    "Got expected log message %r at unexpected level (%s vs %s)"
+                    % (message, logging.getLevelName(self.level), record.levelname)
+                )
+                return True
             self.matched = True
             return False
         return True
 
     def __enter__(self) -> "ExpectLog":
+        if self.level is not None and self.level < self.logger.getEffectiveLevel():
+            self.orig_level = self.logger.level
+            self.logger.setLevel(self.level)
         self.logger.addFilter(self)
         return self
 
@@ -694,6 +715,8 @@ class ExpectLog(logging.Filter):
         value: Optional[BaseException],
         tb: Optional[TracebackType],
     ) -> None:
+        if self.orig_level is not None:
+            self.logger.setLevel(self.orig_level)
         self.logger.removeFilter(self)
         if not typ and self.required and not self.matched:
             raise Exception("did not get expected log message")