From c5c24fc3265998009001f16e015261d2059929fa Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 2 Feb 2023 15:29:35 -0500 Subject: [PATCH 1/4] Reload the pyo3-log configuration when the Python logging configuration changes. --- rust/src/lib.rs | 16 ++++++++++-- rust/src/push/evaluator.rs | 4 +-- rust/src/push/mod.rs | 2 +- synapse/config/logger.py | 42 ++++++++++++++++++------------- tests/test_utils/logging_setup.py | 3 +++ 5 files changed, 44 insertions(+), 23 deletions(-) diff --git a/rust/src/lib.rs b/rust/src/lib.rs index c7b60e58a73b..e66363416079 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,19 @@ fn sum_as_string(a: usize, b: usize) -> PyResult { 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/rust/src/push/evaluator.rs b/rust/src/push/evaluator.rs index aa71202e4379..696adf3ce10e 100644 --- a/rust/src/push/evaluator.rs +++ b/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 } } diff --git a/rust/src/push/mod.rs b/rust/src/push/mod.rs index 7e449f243371..9c04818b5278 100644 --- a/rust/src/push/mod.rs +++ b/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 ); diff --git a/synapse/config/logger.py b/synapse/config/logger.py index 5468b963a2c1..56be970cf9c9 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -35,6 +35,7 @@ from synapse.logging.context import LoggingContextFilter from synapse.logging.filter import MetadataFilter from synapse.types import JsonDict +from synapse.synapse_rust import reset_logging_config from ..util import SYNAPSE_VERSION from ._base import Config, ConfigError @@ -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: """ diff --git a/tests/test_utils/logging_setup.py b/tests/test_utils/logging_setup.py index 9228454c9e78..304c7b98c5c9 100644 --- a/tests/test_utils/logging_setup.py +++ b/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() From 04da7d04a1f7bd35a0f71e9996d1d59bdca7c55d Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 2 Feb 2023 16:14:31 -0500 Subject: [PATCH 2/4] Newsfragment --- changelog.d/14976.bugfix | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/14976.bugfix diff --git a/changelog.d/14976.bugfix b/changelog.d/14976.bugfix new file mode 100644 index 000000000000..0cde046c0e00 --- /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. From 0f5423e054d509d94c8ba99a8e4376f838fff60f Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 2 Feb 2023 16:17:51 -0500 Subject: [PATCH 3/4] Update stubs. --- rust/src/lib.rs | 1 + stubs/synapse/synapse_rust/__init__.pyi | 1 + synapse/config/logger.py | 2 +- 3 files changed, 3 insertions(+), 1 deletion(-) diff --git a/rust/src/lib.rs b/rust/src/lib.rs index e66363416079..ce67f5861183 100644 --- a/rust/src/lib.rs +++ b/rust/src/lib.rs @@ -25,6 +25,7 @@ fn sum_as_string(a: usize, b: usize) -> PyResult { /// 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(); diff --git a/stubs/synapse/synapse_rust/__init__.pyi b/stubs/synapse/synapse_rust/__init__.pyi index 8658d3138f89..d25c60910662 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 56be970cf9c9..56db875b25b1 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -34,8 +34,8 @@ from synapse.logging.context import LoggingContextFilter from synapse.logging.filter import MetadataFilter -from synapse.types import JsonDict from synapse.synapse_rust import reset_logging_config +from synapse.types import JsonDict from ..util import SYNAPSE_VERSION from ._base import Config, ConfigError From 9580baf92603fab260bd82351ffef159e81f4349 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Fri, 3 Feb 2023 07:39:58 -0500 Subject: [PATCH 4/4] Back out explicit target. --- rust/src/push/evaluator.rs | 4 ++-- rust/src/push/mod.rs | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/rust/src/push/evaluator.rs b/rust/src/push/evaluator.rs index 696adf3ce10e..aa71202e4379 100644 --- a/rust/src/push/evaluator.rs +++ b/rust/src/push/evaluator.rs @@ -171,7 +171,7 @@ impl PushRuleEvaluator { Ok(true) => {} Ok(false) => continue 'outer, Err(err) => { - warn!(target: "synapse.synapse_rust","Condition match failed {err}"); + warn!("Condition match failed {err}"); continue 'outer; } } @@ -209,7 +209,7 @@ impl PushRuleEvaluator { Ok(true) => true, Ok(false) => false, Err(err) => { - warn!( target: "synapse.synapse_rust","Condition match failed {err}"); + warn!("Condition match failed {err}"); false } } diff --git a/rust/src/push/mod.rs b/rust/src/push/mod.rs index 9c04818b5278..7e449f243371 100644 --- a/rust/src/push/mod.rs +++ b/rust/src/push/mod.rs @@ -368,7 +368,7 @@ impl PushRules { 2 => push_rules.sender.push(rule), 1 => push_rules.underride.push(rule), _ => { - warn!(target: "synapse.synapse_rust", + warn!( "Unrecognized priority class for rule {}: {}", rule.rule_id, rule.priority_class );