Add spam detection in test-backend output.

[thedeveloperr]

This commit adds automatic spam detection in output printed to
stderr and stdout by test-backend while running instances of
ZulipTestCase in parallel mode.
It also prints the test file and method that produced the
spam.

#1587

• Add flag to disable the spam detection.

Testing Plan:

1. Added print statements in test cases randomly and confirmed if the it's being caught.
2. Removed few commits that suppressed logs using assertLogs and ensured that spam was caught by the script and right test that printed the spam.

GIFs or Screenshots:

[thedeveloperr]

@timabbott Please give a review on this approach. This was the best I was able to do after alot of failed iteration to detect spam and also point to the test that produced that spam

[showell]

typo: "onsole" -> "console"

[timabbott]

I'd encourage using the same name for a variable like this, rather than having 3 versions:

• BAN_TEST_OUTPUT_EXTRA_SPAM, ban-extra-output, ban_spam.

[timabbott]

Maybe the name should be --ban-console-output as the name and use that consistently (there should be no references to "spam" to "output_extra" in this PR)

[timabbott]

Let's format this using f""" to be a more readable block. And I'd replace "Spam" with "Output" and "SPAM DETECTED" with "UNEXPECTED CONSOLE OUTPUT" and maybe some text about the goal of having test-backend output be clean.

[timabbott]

Let's put the comments on the line before the expression, rather than the same line; it'll be more readable that way.

We may want to do a bit of work to remove some of these output lines from the test-backend default output as a follow-up project. E.g. @showell is the "URL coverage report" something we should just delete at this point, now that we have more powerful tools for checking that we've tested all our API endpoints?

And I feel like the "Destroying test database for alias" type output could be hidden behind a verbose flag.

[timabbott]

You might be able to deduplicate these two classes; they're nearly the same. Not sure if it's worth it.

[timabbott]

This bundle probably better belongs in test_runner.py than test_helpers.py -- the latter is for things we might import from an individual test.

[timabbott]

Actually, let's put this new code in a new file, zerver/lib/test_console_output.py ; I think that'll be happier. (I'd misunderstood it as being called not from test_classes.py).

[timabbott]

@thedeveloperr thanks for working on this! The approach seems viable; I posted a bunch of comments on cleaning up the code.

[timabbott]

You'll want to add # nocoverage on this function, I think, since one path or the other is going to be not run in every individual test run.

[thedeveloperr]

@timabbott Do we need test coverage for spam detection and Tee class ? It is itself called in tests so I was bit confused how I could write test for something that is called inside a test, and that too in ZulipTestCase run method.

[timabbott]

The right way to handle coverage is to put # nocoverage on the def line itself, I think.

[timabbott]

After moving the coverage change, I made these documentation tweaks:

(zulip-py3-venv) tabbott@coset:~/zulip$ git diff
diff --git a/tools/test-backend b/tools/test-backend
index 3cee63516e..794a306aee 100755
--- a/tools/test-backend
+++ b/tools/test-backend
@@ -263,7 +263,7 @@ def main() -> None:
     parser.add_argument('args', nargs='*')
     parser.add_argument('--ban-console-output', dest='ban_console_output',
                         action="store_true",
-                        default=False, help='Throw error on detecting output in stdout and stderr produced by code under tests.')
+                        default=False, help='Require stdout and stderr to be clean of unexpected output.')
 
     options = parser.parse_args()
     if options.ban_console_output:
diff --git a/zerver/lib/test_classes.py b/zerver/lib/test_classes.py
index 3f4758a7de..8a6172ea5d 100644
--- a/zerver/lib/test_classes.py
+++ b/zerver/lib/test_classes.py
@@ -127,23 +127,24 @@ class ZulipTestCase(TestCase):
             test_result = super(ZulipTestCase, self).run(result)
         if extra_output_finder.full_extra_output:
             exception_message = f"""
-            ---- UNEXPECTED CONSOLE OUTPUT DETECTED ----
-            Sometimes bugs are introduced where extra
-            console output shows up in the test-backend
-            output making it harder to read our test
-            output.
-            This check detects extra console output due
-            to a logger or some other source printing
-            to stdout or stderr. Please see the test and
-            extra output detected
-
-            Test:
-            {self.id()}
-
-            Extra Output:
-            {extra_output_finder.full_extra_output}
-            --------------------------------------------
-            """
+---- 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
 

With those changes, this lgtm; I'm planning to merge after looking at our generic testing docs to see if this feature needs a mention.

[timabbott]

I pushed back to this PR after those changes and adding another documentation commit (that also enables the option in CI); will merge if this passes CI.

[thedeveloperr]

All tests passed.

[timabbott]

Merged, thanks for all your hard work on this @thedeveloperr!