testing: Deprecate environment-dependent behavior in ExpectLog

ExpectLog is sensitive to the difference between tornado.testing.main
(which sets the logging level to info) and most other test runners,
which do not. In the future ExpectLog will match WARNING and above
by default; matching lower levels without using the ``level`` argument
is deprecated.

Fix one test in httpserver_test.py that is affected by this.

diff --git a/tornado/test/httpserver_test.py b/tornado/test/httpserver_test.py
index 146ed781ca7c01d5e61186f1ed59726c68784024..cea31d2e9e9e5b6d6a6537253b3b4d1c9490da8e 100644 (file)
--- a/tornado/test/httpserver_test.py
+++ b/tornado/test/httpserver_test.py
@@ -754,7 +754,7 @@ class UnixSocketTest(AsyncTestCase):
     def test_unix_socket_bad_request(self):
         # Unix sockets don't have remote addresses so they just return an
         # empty string.
-        with ExpectLog(gen_log, "Malformed HTTP message from"):
+        with ExpectLog(gen_log, "Malformed HTTP message from", level=logging.INFO):
             self.stream.write(b"garbage\r\n\r\n")
             response = yield self.stream.read_until_close()
         self.assertEqual(response, b"HTTP/1.1 400 Bad Request\r\n\r\n")

diff --git a/tornado/test/websocket_test.py b/tornado/test/websocket_test.py
index 53d5cde2c0ed2870f7c425fe409fecb1b964d305..8ce3d512f20b125c130d260990469bc0c333ced6 100644 (file)
--- a/tornado/test/websocket_test.py
+++ b/tornado/test/websocket_test.py
@@ -388,7 +388,7 @@ class WebSocketTest(WebSocketBaseTestCase):
         sock, port = bind_unused_port()
         sock.close()
         with self.assertRaises(IOError):
-            with ExpectLog(gen_log, ".*"):
+            with ExpectLog(gen_log, ".*", required=False):
                 yield websocket_connect(
                     "ws://127.0.0.1:%d/" % port, connect_timeout=3600
                 )

diff --git a/tornado/testing.py b/tornado/testing.py
index fcad60c173a6a587da7cb480509c553d324f6b50..c786a2e5cd0fe2655dfc31a85c2fbfcc83c96561 100644 (file)
--- a/tornado/testing.py
+++ b/tornado/testing.py
@@ -724,28 +724,37 @@ class ExpectLog(logging.Filter):
     ) -> None:
         """Constructs an ExpectLog context manager.
 
-        :param logger: Logger object (or name of logger) to watch.  Pass
-            an empty string to watch the root logger.
-        :param regex: Regular expression to match.  Any log entries on
-            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 logger: Logger object (or name of logger) to watch.  Pass an
+            empty string to watch the root logger.
+        :param regex: Regular expression to match.  Any log entries on 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.
+            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.
+
+        .. deprecated:: 6.3
+           In Tornado 7.0, only ``WARNING`` and higher logging levels will be
+           matched by default. To match ``INFO`` and lower levels, the ``level``
+           argument must be used. This is changing to minimize differences
+           between ``tornado.testing.main`` (which enables ``INFO`` logs by
+           default) and most other test runners (including those in IDEs)
+           which have ``INFO`` logs disabled by default.
         """
         if isinstance(logger, basestring_type):
             logger = logging.getLogger(logger)
         self.logger = logger
         self.regex = re.compile(regex)
         self.required = required
-        self.matched = False
+        # matched and deprecated_level_matched are a counter for the respective event.
+        self.matched = 0
+        self.deprecated_level_matched = 0
         self.logged_stack = False
         self.level = level
         self.orig_level = None  # type: Optional[int]
@@ -755,13 +764,20 @@ class ExpectLog(logging.Filter):
             self.logged_stack = True
         message = record.getMessage()
         if self.regex.match(message):
+            if self.level is None and record.levelno < logging.WARNING:
+                # We're inside the logging machinery here so generating a DeprecationWarning
+                # here won't be reported cleanly (if warnings-as-errors is enabled, the error
+                # just gets swallowed by the logging module), and even if it were it would
+                # have the wrong stack trace. Just remember this fact and report it in
+                # __exit__ instead.
+                self.deprecated_level_matched += 1
             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
+            self.matched += 1
             return False
         return True
 
@@ -783,6 +799,15 @@ class ExpectLog(logging.Filter):
         self.logger.removeFilter(self)
         if not typ and self.required and not self.matched:
             raise Exception("did not get expected log message")
+        if (
+            not typ
+            and self.required
+            and (self.deprecated_level_matched >= self.matched)
+        ):
+            warnings.warn(
+                "ExpectLog matched at INFO or below without level argument",
+                DeprecationWarning,
+            )
 
 
 # From https://nedbatchelder.com/blog/201508/using_context_managers_in_test_setup.html