From: Ben Darnell Date: Sun, 19 Jan 2020 20:11:54 +0000 (-0500) Subject: testing: Add level argument to ExpectLog X-Git-Tag: v6.1.0b1~40^2~2 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=85192e11560a5fae87b4e7ed6804828ab3826d50;p=thirdparty%2Ftornado.git testing: Add level argument to ExpectLog 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) --- diff --git a/tornado/test/httpserver_test.py b/tornado/test/httpserver_test.py index 63052ba12..ed91a99ff 100644 --- a/tornado/test/httpserver_test.py +++ b/tornado/test/httpserver_test.py @@ -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: diff --git a/tornado/test/iostream_test.py b/tornado/test/iostream_test.py index d9e2c666b..359269cac 100644 --- a/tornado/test/iostream_test.py +++ b/tornado/test/iostream_test.py @@ -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: diff --git a/tornado/test/simple_httpclient_test.py b/tornado/test/simple_httpclient_test.py index a883786dc..0f2c252fe 100644 --- a/tornado/test/simple_httpclient_test.py +++ b/tornado/test/simple_httpclient_test.py @@ -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) diff --git a/tornado/testing.py b/tornado/testing.py index da275cbce..4bc83e462 100644 --- a/tornado/testing.py +++ b/tornado/testing.py @@ -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")