Fix for structured logging tests stomping on logs

changelog.d/6023.misc

@@ -0,0 +1 @@
+Fix the structured logging tests stomping on the global log configuration for subsequent tests.

synapse/config/logger.py

@@ -21,7 +21,7 @@
 
 import yaml
 
-from twisted.logger import STDLibLogObserver, globalLogBeginner
+from twisted.logger import LogBeginner, Logger, STDLibLogObserver, globalLogBeginner
 
 import synapse
 from synapse.app import _base as appbase
@@ -124,7 +124,7 @@ def generate_files(self, config, config_dir_path):
                 log_config_file.write(DEFAULT_LOG_CONFIG.substitute(log_file=log_file))
 
 
-def _setup_stdlib_logging(config, log_config):
+def _setup_stdlib_logging(config, log_config, logBeginner: LogBeginner):
     """
     Set up Python stdlib logging.
     """
@@ -165,12 +165,12 @@ def _log(event):
 
         return observer(event)
 
-    globalLogBeginner.beginLoggingTo(
-        [_log], redirectStandardIO=not config.no_redirect_stdio
-    )
+    logBeginner.beginLoggingTo([_log], redirectStandardIO=not config.no_redirect_stdio)
     if not config.no_redirect_stdio:
         print("Redirected stdout/stderr to logs")
 
+    return observer
+
 
 def _reload_stdlib_logging(*args, log_config=None):
     logger = logging.getLogger("")
@@ -181,7 +181,9 @@ def _reload_stdlib_logging(*args, log_config=None):
     logging.config.dictConfig(log_config)
 
 
-def setup_logging(hs, config, use_worker_options=False):
+def setup_logging(
+    hs, config, use_worker_options=False, logBeginner: LogBeginner = globalLogBeginner
+) -> Logger:
     """
     Set up the logging subsystem.
 
@@ -191,6 +193,8 @@ def setup_logging(hs, config, use_worker_options=False):
 
         use_worker_options (bool): True to use the 'worker_log_config' option
             instead of 'log_config'.
+
+        logBeginner: The Twisted logBeginner to use.
     """
     log_config = config.worker_log_config if use_worker_options else config.log_config
 
@@ -210,14 +214,18 @@ def read_config(*args, callback=None):
     log_config_body = read_config()
 
     if log_config_body and log_config_body.get("structured") is True:
-        setup_structured_logging(hs, config, log_config_body)
+        logger = setup_structured_logging(
+            hs, config, log_config_body, logBeginner=logBeginner
+        )
         appbase.register_sighup(read_config, callback=reload_structured_logging)
     else:
-        _setup_stdlib_logging(config, log_config_body)
+        logger = _setup_stdlib_logging(config, log_config_body, logBeginner=logBeginner)
         appbase.register_sighup(read_config, callback=_reload_stdlib_logging)
 
     # make sure that the first thing we log is a thing we can grep backwards
     # for
     logging.warn("***** STARTING SERVER *****")
     logging.warn("Server %s version %s", sys.argv[0], get_version_string(synapse))
     logging.info("Server hostname: %s", config.server_name)
+
+    return logger

synapse/logging/_structured.py

@@ -33,7 +33,6 @@
     LogLevelFilterPredicate,
     LogPublisher,
     eventAsText,
-    globalLogBeginner,
     jsonFileLogObserver,
 )
 
@@ -265,7 +264,7 @@ def setup_structured_logging(
     hs,
     config,
     log_config: dict,
-    logBeginner: LogBeginner = globalLogBeginner,
+    logBeginner: LogBeginner,
     redirect_stdlib_logging: bool = True,
 ) -> LogPublisher:
     """

tests/logging/test_structured.py

@@ -13,6 +13,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import logging
 import os
 import os.path
 import shutil
@@ -33,7 +34,20 @@ def beginLoggingTo(self, observers, **kwargs):
         self.observers = observers
 
 
-class StructuredLoggingTestCase(HomeserverTestCase):
+class StructuredLoggingTestBase(object):
+    """
+    Test base that registers a cleanup handler to reset the stdlib log handler
+    to 'unset'.
+    """
+
+    def prepare(self, reactor, clock, hs):
+        def _cleanup():
+            logging.getLogger("synapse").setLevel(0)
+
+        self.addCleanup(_cleanup)
+
+
+class StructuredLoggingTestCase(StructuredLoggingTestBase, HomeserverTestCase):
     """
     Tests for Synapse's structured logging support.
     """
@@ -139,7 +153,9 @@ def test_collects_logcontext(self):
         self.assertEqual(logs[0]["request"], "somereq")
 
 
-class StructuredLoggingConfigurationFileTestCase(HomeserverTestCase):
+class StructuredLoggingConfigurationFileTestCase(
+    StructuredLoggingTestBase, HomeserverTestCase
+):
     def make_homeserver(self, reactor, clock):
 
         tempdir = self.mktemp()
@@ -179,10 +195,11 @@ def test_log_output(self):
         """
         When a structured logging config is given, Synapse will use it.
         """
-        setup_logging(self.hs, self.hs.config)
+        beginner = FakeBeginner()
+        publisher = setup_logging(self.hs, self.hs.config, logBeginner=beginner)
 
         # Make a logger and send an event
-        logger = Logger(namespace="tests.logging.test_structured")
+        logger = Logger(namespace="tests.logging.test_structured", observer=publisher)
 
         with LoggingContext("testcontext", request="somereq"):
             logger.info("Hello there, {name}!", name="steve")

tests/logging/test_terse_json.py

@@ -23,10 +23,10 @@
 from tests.server import connect_client
 from tests.unittest import HomeserverTestCase
 
-from .test_structured import FakeBeginner
+from .test_structured import FakeBeginner, StructuredLoggingTestBase
 
 
-class TerseJSONTCPTestCase(HomeserverTestCase):
+class TerseJSONTCPTestCase(StructuredLoggingTestBase, HomeserverTestCase):
     def test_log_output(self):
         """
         The Terse JSON outputter delivers simplified structured logs over TCP.