tests: Add extra console output detection in test-backend output.

This commit adds automatic detection of extra output (other than
printed by testing library or tools) in stderr and stdout by code under
test test-backend when it is run with flag --ban-console-output.
It also prints the test that produced the extra console output.

Fixes: #1587.

tools/test-backend

@@ -108,6 +108,7 @@ not_yet_fully_covered = {path for target in [
     'zerver/lib/server_initialization.py',
     'zerver/lib/test_fixtures.py',
     'zerver/lib/test_runner.py',
+    'zerver/lib/test_console_output.py',
     'zerver/openapi/python_examples.py',
     # Tornado should ideally have full coverage, but we're not there.
     'zerver/tornado/autoreload.py',
@@ -260,8 +261,14 @@ def main() -> None:
                         default=False,
                         help=("Generate Stripe test fixtures by making requests to Stripe test network"))
     parser.add_argument('args', nargs='*')
+    parser.add_argument('--ban-console-output', dest='ban_console_output',
+                        action="store_true",
+                        default=False, help='Require stdout and stderr to be clean of unexpected output.')
 
     options = parser.parse_args()
+    if options.ban_console_output:
+        os.environ["BAN_CONSOLE_OUTPUT"] = "1"
+
     args = options.args
     parallel = options.processes
     include_webhooks = options.coverage or options.include_webhooks

zerver/lib/test_classes.py

@@ -6,7 +6,7 @@ import tempfile
 import urllib
 from contextlib import contextmanager
 from typing import Any, Dict, Iterable, Iterator, List, Optional, Sequence, Set, Tuple, Union
-from unittest import mock
+from unittest import TestResult, mock
 
 import orjson
 from django.apps import apps
@@ -41,6 +41,12 @@ from zerver.lib.streams import (
     create_stream_if_needed,
     get_default_value_for_history_public_to_subscribers,
 )
+from zerver.lib.test_console_output import (
+    ExtraConsoleOutputFinder,
+    ExtraConsoleOutputInTestException,
+    TeeStderrAndFindExtraConsoleOutput,
+    TeeStdoutAndFindExtraConsoleOutput,
+)
 from zerver.lib.test_helpers import find_key_by_email, instrument_url
 from zerver.lib.users import get_api_key
 from zerver.lib.validator import check_string
@@ -113,6 +119,35 @@ class ZulipTestCase(TestCase):
                 self.mock_ldap.reset()
             self.mock_initialize.stop()
 
+    def run(self, result: Optional[TestResult]=None) -> Optional[TestResult]:  # nocoverage
+        if not settings.BAN_CONSOLE_OUTPUT:
+            return super(ZulipTestCase, self).run(result)
+        extra_output_finder = ExtraConsoleOutputFinder()
+        with TeeStderrAndFindExtraConsoleOutput(extra_output_finder), TeeStdoutAndFindExtraConsoleOutput(extra_output_finder):
+            test_result = super(ZulipTestCase, self).run(result)
+        if extra_output_finder.full_extra_output:
+            exception_message = f"""
+---- UNEXPECTED CONSOLE OUTPUT DETECTED ----
+
+To ensure that we never miss important error output/warnings,
+we require test-backend to have clean console output.
+
+This message usually is triggered by forgotten debugging print()
+statements or new logging statements.  For the latter, you can
+use `with self.assertLogs()` to capture and verify the log output;
+use `git grep assertLogs` to see dozens of correct examples.
+
+You should be able to quickly reproduce this failure with:
+
+test-backend --ban-console-output {self.id()}
+
+Output:
+{extra_output_finder.full_extra_output}
+--------------------------------------------
+"""
+            raise ExtraConsoleOutputInTestException(exception_message)
+        return test_result
+
     '''
     WRAPPER_COMMENT:
 

zerver/lib/test_console_output.py

@@ -0,0 +1,114 @@
+import logging
+import re
+import sys
+from types import TracebackType
+from typing import Iterable, Optional, Type, cast
+
+
+class ExtraConsoleOutputInTestException(Exception):
+    pass
+
+class ExtraConsoleOutputFinder:
+    def __init__(self) -> None:
+        self.latest_test_name = ""
+        valid_line_patterns = [
+            # Example: Running zerver.tests.test_attachments.AttachmentsTests.test_delete_unauthenticated
+            "^Running ",
+
+            # Example: ** Test is TOO slow: analytics.tests.test_counts.TestRealmActiveHumans.test_end_to_end (0.581 s)
+            "^\\*\\* Test is TOO slow: ",
+            "^----------------------------------------------------------------------",
+
+            # Example: INFO: URL coverage report is in var/url_coverage.txt
+            "^INFO: URL coverage report is in",
+
+            # Example: INFO: Try running: ./tools/create-test-api-docs
+            "^INFO: Try running:",
+
+            # Example: -- Running tests in parallel mode with 4 processes
+            "^-- Running tests in",
+            "^OK",
+
+            # Example: Ran 2139 tests in 115.659s
+            "^Ran [0-9]+ tests in",
+
+            # Destroying test database for alias 'default'...
+            "^Destroying test database for alias ",
+            "^Using existing clone",
+            "^\\*\\* Skipping ",
+        ]
+        self.compiled_line_patterns = []
+        for pattern in valid_line_patterns:
+            self.compiled_line_patterns.append(re.compile(pattern))
+        self.full_extra_output = ""
+
+    def find_extra_output(self, data: str) -> None:
+        lines = data.split('\n')
+        for line in lines:
+            if not line:
+                continue
+            found_extra_output = True
+            for compiled_pattern in self.compiled_line_patterns:
+                if compiled_pattern.match(line):
+                    found_extra_output = False
+                    break
+            if found_extra_output:
+                self.full_extra_output += f'{line}\n'
+
+class TeeStderrAndFindExtraConsoleOutput():
+    def __init__(self, extra_output_finder: ExtraConsoleOutputFinder) -> None:
+        self.stderr_stream = sys.stderr
+
+        # get shared console handler instance from any logger that have it
+        self.console_log_handler = cast(logging.StreamHandler, logging.getLogger('django.server').handlers[0])
+
+        assert isinstance(self.console_log_handler, logging.StreamHandler)
+        assert self.console_log_handler.stream == sys.stderr
+        self.extra_output_finder = extra_output_finder
+
+    def __enter__(self) -> None:
+        sys.stderr = self  # type: ignore[assignment] # Doing tee by swapping stderr stream with custom file like class
+        self.console_log_handler.stream = self  # type: ignore[assignment] # Doing tee by swapping stderr stream with custom file like class
+
+    def __exit__(self, exc_type: Optional[Type[BaseException]],
+                 exc_value: Optional[BaseException],
+                 traceback: Optional[TracebackType]) -> None:
+        sys.stderr = self.stderr_stream
+        self.console_log_handler.stream = sys.stderr
+
+    def write(self, data: str) -> None:
+        self.stderr_stream.write(data)
+        self.extra_output_finder.find_extra_output(data)
+
+    def writelines(self, data: Iterable[str]) -> None:
+        self.stderr_stream.writelines(data)
+        lines = "".join(data)
+        self.extra_output_finder.find_extra_output(lines)
+
+    def flush(self) -> None:
+        self.stderr_stream.flush()
+
+class TeeStdoutAndFindExtraConsoleOutput():
+    def __init__(self, extra_output_finder: ExtraConsoleOutputFinder) -> None:
+        self.stdout_stream = sys.stdout
+        self.extra_output_finder = extra_output_finder
+
+    def __enter__(self) -> None:
+        sys.stdout = self  # type: ignore[assignment] # Doing tee by swapping stderr stream with custom file like class
+
+    def __exit__(self, exc_type: Optional[Type[BaseException]],
+                 exc_value: Optional[BaseException],
+                 traceback: Optional[TracebackType]) -> None:
+        sys.stdout = self.stdout_stream
+
+    def write(self, data: str) -> None:
+        self.stdout_stream.write(data)
+        self.extra_output_finder.find_extra_output(data)
+
+    def writelines(self, data: Iterable[str]) -> None:
+        self.stdout_stream.writelines(data)
+        lines = "".join(data)
+        self.extra_output_finder.find_extra_output(lines)
+
+    def flush(self) -> None:
+        self.stdout_stream.flush()

zproject/computed_settings.py

@@ -104,6 +104,8 @@ CASPER_TESTS = False
 RUNNING_OPENAPI_CURL_TEST = False
 # This is overridden in test_settings.py for the test suites
 GENERATE_STRIPE_FIXTURES = False
+# This is overridden in test_settings.py for the test suites
+BAN_CONSOLE_OUTPUT = False
 
 # Google Compute Engine has an /etc/boto.cfg that is "nicely
 # configured" to work with GCE's storage service.  However, their

zproject/test_extra_settings.py

@@ -56,6 +56,9 @@ if "RUNNING_OPENAPI_CURL_TEST" in os.environ:
 if "GENERATE_STRIPE_FIXTURES" in os.environ:
     GENERATE_STRIPE_FIXTURES = True
 
+if "BAN_CONSOLE_OUTPUT" in os.environ:
+    BAN_CONSOLE_OUTPUT = True
+
 # Decrease the get_updates timeout to 1 second.
 # This allows CasperJS to proceed quickly to the next test step.
 POLL_TIMEOUT = 1000