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.
This commit is contained in:
Patrick Cloke 2023-02-03 08:27:31 -05:00 committed by GitHub
parent da05b70af5
commit 8e9fc28c6a
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 44 additions and 20 deletions

1
changelog.d/14976.bugfix Normal file
View File

@ -0,0 +1 @@
Fix a bug introduced in Synapse 1.68.0 where logging from the Rust module was not properly logged.

View File

@ -1,7 +1,13 @@
use lazy_static::lazy_static;
use pyo3::prelude::*; use pyo3::prelude::*;
use pyo3_log::ResetHandle;
pub mod push; 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. /// 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. /// 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()) 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. /// The entry point for defining the Python module.
#[pymodule] #[pymodule]
fn synapse_rust(py: Python<'_>, m: &PyModule) -> PyResult<()> { 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!(sum_as_string, m)?)?;
m.add_function(wrap_pyfunction!(get_rust_file_digest, 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)?; push::register_module(py, m)?;

View File

@ -1,2 +1,3 @@
def sum_as_string(a: int, b: int) -> str: ... def sum_as_string(a: int, b: int) -> str: ...
def get_rust_file_digest() -> str: ... def get_rust_file_digest() -> str: ...
def reset_logging_config() -> None: ...

View File

@ -34,6 +34,7 @@ from twisted.logger import (
from synapse.logging.context import LoggingContextFilter from synapse.logging.context import LoggingContextFilter
from synapse.logging.filter import MetadataFilter from synapse.logging.filter import MetadataFilter
from synapse.synapse_rust import reset_logging_config
from synapse.types import JsonDict from synapse.types import JsonDict
from ..util import SYNAPSE_VERSION from ..util import SYNAPSE_VERSION
@ -200,24 +201,6 @@ def _setup_stdlib_logging(
""" """
Set up Python standard library 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 # We add a log record factory that runs all messages through the
# LoggingContextFilter so that we get the context *at the time we log* # LoggingContextFilter so that we get the context *at the time we log*
@ -237,6 +220,26 @@ def _setup_stdlib_logging(
logging.setLogRecordFactory(factory) 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 # Route Twisted's native logging through to the standard library logging
# system. # system.
observer = STDLibLogObserver() observer = STDLibLogObserver()
@ -294,6 +297,9 @@ def _load_logging_config(log_config_path: str) -> None:
logging.config.dictConfig(log_config) 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: def _reload_logging_config(log_config_path: Optional[str]) -> None:
""" """

View File

@ -17,6 +17,7 @@ import os
import twisted.logger import twisted.logger
from synapse.logging.context import LoggingContextFilter from synapse.logging.context import LoggingContextFilter
from synapse.synapse_rust import reset_logging_config
class ToTwistedHandler(logging.Handler): class ToTwistedHandler(logging.Handler):
@ -52,3 +53,5 @@ def setup_logging():
log_level = os.environ.get("SYNAPSE_TEST_LOG_LEVEL", "ERROR") log_level = os.environ.get("SYNAPSE_TEST_LOG_LEVEL", "ERROR")
root_logger.setLevel(log_level) root_logger.setLevel(log_level)
reset_logging_config()