Reload the pyo3-log config when the Python logging config changes.

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.

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)?;
 

rust/src/push/evaluator.rs

@@ -171,7 +171,7 @@ impl PushRuleEvaluator {
                     Ok(true) => {}
                     Ok(false) => continue 'outer,
                     Err(err) => {
-                        warn!("Condition match failed {err}");
+                        warn!(target: "synapse.synapse_rust","Condition match failed {err}");
                         continue 'outer;
                     }
                 }
@@ -209,7 +209,7 @@ impl PushRuleEvaluator {
             Ok(true) => true,
             Ok(false) => false,
             Err(err) => {
-                warn!("Condition match failed {err}");
+                warn!( target: "synapse.synapse_rust","Condition match failed {err}");
                 false
             }
         }

rust/src/push/mod.rs

@@ -368,7 +368,7 @@ impl PushRules {
                 2 => push_rules.sender.push(rule),
                 1 => push_rules.underride.push(rule),
                 _ => {
-                    warn!(
+                    warn!(target: "synapse.synapse_rust",
                         "Unrecognized priority class for rule {}: {}",
                         rule.rule_id, rule.priority_class
                     );

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: ...

synapse/config/logger.py

@@ -34,6 +34,7 @@
 
 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 factory(*args: Any, **kwargs: Any) -> logging.LogRecord:
 
     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:
     """

tests/test_utils/logging_setup.py

@@ -17,6 +17,7 @@
 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()