Reload the pyo3-log config when the Python logging config changes. (#14976)

Since pyo3-log is initialized very early in the Python start-up
it caches the state of the loggers before they're fully initialized
(and thus are essentially disabled). Whenever we reload the
logging configuration we now also tell pyo3-log to discard
any cached logging configuration it has; it will refetch the
current logging configuration from Python at the next point
it logs.

This fixes Rust log lines not appearing in the homeserver logs.

5 files changed, 44 insertions, 20 deletions

diff --git a/changelog.d/14976.bugfix b/changelog.d/14976.bugfix
new file mode 100644
index 0000000000..0cde046c0e
--- /dev/null
+++ b/changelog.d/14976.bugfix
@@ -0,0 +1 @@
+Fix a bug introduced in Synapse 1.68.0 where logging from the Rust module was not properly logged.
diff --git a/rust/src/lib.rs b/rust/src/lib.rs
index c7b60e58a7..ce67f58611 100644
--- a/rust/src/lib.rs
+++ b/rust/src/lib.rs
@@ -1,7 +1,13 @@
+use lazy_static::lazy_static;
 use pyo3::prelude::*;
+use pyo3_log::ResetHandle;
 
 pub mod push;
 
+lazy_static! {
+    static ref LOGGING_HANDLE: ResetHandle = pyo3_log::init();
+}
+
 /// Returns the hash of all the rust source files at the time it was compiled.
 ///
 /// Used by python to detect if the rust library is outdated.
@@ -17,13 +23,20 @@ fn sum_as_string(a: usize, b: usize) -> PyResult<String> {
     Ok((a + b).to_string())
 }
 
+/// Reset the cached logging configuration of pyo3-log to pick up any changes
+/// in the Python logging configuration.
+///
+#[pyfunction]
+fn reset_logging_config() {
+    LOGGING_HANDLE.reset();
+}
+
 /// The entry point for defining the Python module.
 #[pymodule]
 fn synapse_rust(py: Python<'_>, m: &PyModule) -> PyResult<()> {
-    pyo3_log::init();
-
     m.add_function(wrap_pyfunction!(sum_as_string, m)?)?;
     m.add_function(wrap_pyfunction!(get_rust_file_digest, m)?)?;
+    m.add_function(wrap_pyfunction!(reset_logging_config, m)?)?;
 
     push::register_module(py, m)?;
 
diff --git a/stubs/synapse/synapse_rust/__init__.pyi b/stubs/synapse/synapse_rust/__init__.pyi
index 8658d3138f..d25c609106 100644
--- a/stubs/synapse/synapse_rust/__init__.pyi
+++ b/stubs/synapse/synapse_rust/__init__.pyi
@@ -1,2 +1,3 @@
 def sum_as_string(a: int, b: int) -> str: ...
 def get_rust_file_digest() -> str: ...
+def reset_logging_config() -> None: ...
diff --git a/synapse/config/logger.py b/synapse/config/logger.py
index 5468b963a2..56db875b25 100644
--- a/synapse/config/logger.py
+++ b/synapse/config/logger.py
@@ -34,6 +34,7 @@ from twisted.logger import (
 
 from synapse.logging.context import LoggingContextFilter
 from synapse.logging.filter import MetadataFilter
+from synapse.synapse_rust import reset_logging_config
 from synapse.types import JsonDict
 
 from ..util import SYNAPSE_VERSION
@@ -200,24 +201,6 @@ def _setup_stdlib_logging(
     """
     Set up Python standard library logging.
     """
-    if log_config_path is None:
-        log_format = (
-            "%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s"
-            " - %(message)s"
-        )
-
-        logger = logging.getLogger("")
-        logger.setLevel(logging.INFO)
-        logging.getLogger("synapse.storage.SQL").setLevel(logging.INFO)
-
-        formatter = logging.Formatter(log_format)
-
-        handler = logging.StreamHandler()
-        handler.setFormatter(formatter)
-        logger.addHandler(handler)
-    else:
-        # Load the logging configuration.
-        _load_logging_config(log_config_path)
 
     # We add a log record factory that runs all messages through the
     # LoggingContextFilter so that we get the context *at the time we log*
@@ -237,6 +220,26 @@ def _setup_stdlib_logging(
 
     logging.setLogRecordFactory(factory)
 
+    # Configure the logger with the initial configuration.
+    if log_config_path is None:
+        log_format = (
+            "%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s"
+            " - %(message)s"
+        )
+
+        logger = logging.getLogger("")
+        logger.setLevel(logging.INFO)
+        logging.getLogger("synapse.storage.SQL").setLevel(logging.INFO)
+
+        formatter = logging.Formatter(log_format)
+
+        handler = logging.StreamHandler()
+        handler.setFormatter(formatter)
+        logger.addHandler(handler)
+    else:
+        # Load the logging configuration.
+        _load_logging_config(log_config_path)
+
     # Route Twisted's native logging through to the standard library logging
     # system.
     observer = STDLibLogObserver()
@@ -294,6 +297,9 @@ def _load_logging_config(log_config_path: str) -> None:
 
     logging.config.dictConfig(log_config)
 
+    # Blow away the pyo3-log cache so that it reloads the configuration.
+    reset_logging_config()
+
 
 def _reload_logging_config(log_config_path: Optional[str]) -> None:
     """
diff --git a/tests/test_utils/logging_setup.py b/tests/test_utils/logging_setup.py
index 9228454c9e..304c7b98c5 100644
--- a/tests/test_utils/logging_setup.py
+++ b/tests/test_utils/logging_setup.py
@@ -17,6 +17,7 @@ import os
 import twisted.logger
 
 from synapse.logging.context import LoggingContextFilter
+from synapse.synapse_rust import reset_logging_config
 
 
 class ToTwistedHandler(logging.Handler):
@@ -52,3 +53,5 @@ def setup_logging():
 
     log_level = os.environ.get("SYNAPSE_TEST_LOG_LEVEL", "ERROR")
     root_logger.setLevel(log_level)
+
+    reset_logging_config()