From 68b40c31edf6bd3553027b0f0c1da11da552552c Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 10 Dec 2020 09:25:36 -0500 Subject: [PATCH 1/6] Remove dead code. This code is never called as of #8607. --- synapse/logging/context.py | 11 ----------- 1 file changed, 11 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index ca0c774cc5bc..1267886d88a6 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -203,10 +203,6 @@ def __str__(self): def copy_to(self, record): pass - def copy_to_twisted_log_entry(self, record): - record["request"] = None - record["scope"] = None - def start(self, rusage: "Optional[resource._RUsage]"): pass @@ -372,13 +368,6 @@ def copy_to(self, record) -> None: # we also track the current scope: record.scope = self.scope - def copy_to_twisted_log_entry(self, record) -> None: - """ - Copy logging fields from this context to a Twisted log record. - """ - record["request"] = self.request - record["scope"] = self.scope - def start(self, rusage: "Optional[resource._RUsage]") -> None: """ Record that this logcontext is currently running. From 1bd6c9f049b79825fe174cbc58976702fd996a76 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 10 Dec 2020 09:26:22 -0500 Subject: [PATCH 2/6] Simplify the init args for LoggingContextFilter. This makes the LoggingContextFilter a bit more specific, but the flexibility was unused and this is a hot codepath. --- synapse/config/logger.py | 2 +- synapse/logging/context.py | 10 +++------- tests/logging/test_terse_json.py | 2 +- tests/test_utils/logging_setup.py | 2 +- 4 files changed, 6 insertions(+), 10 deletions(-) diff --git a/synapse/config/logger.py b/synapse/config/logger.py index d4e887a3e08c..4df3f93c1cd8 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -206,7 +206,7 @@ def _setup_stdlib_logging(config, log_config_path, logBeginner: LogBeginner) -> # filter options, but care must when using e.g. MemoryHandler to buffer # writes. - log_context_filter = LoggingContextFilter(request="") + log_context_filter = LoggingContextFilter() log_metadata_filter = MetadataFilter({"server_name": config.server_name}) old_factory = logging.getLogRecordFactory() diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 1267886d88a6..e808f92c2b70 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -531,13 +531,10 @@ def record_event_fetch(self, event_count: int) -> None: class LoggingContextFilter(logging.Filter): """Logging filter that adds values from the current logging context to each record. - Args: - **defaults: Default values to avoid formatters complaining about - missing fields """ - def __init__(self, **defaults) -> None: - self.defaults = defaults + def __init__(self, request: str = ""): + self._default_request = request def filter(self, record) -> Literal[True]: """Add each fields from the logging contexts to the record. @@ -545,8 +542,7 @@ def filter(self, record) -> Literal[True]: True to include the record in the log output. """ context = current_context() - for key, value in self.defaults.items(): - setattr(record, key, value) + record.request = self._default_request # context should never be None, but if it somehow ends up being, then # we end up in a death spiral of infinite loops, so let's check, for diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index f6e7e5fdaa8c..576aeb35ec66 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -117,7 +117,7 @@ def test_with_context(self): """ handler = logging.StreamHandler(self.output) handler.setFormatter(JsonFormatter()) - handler.addFilter(LoggingContextFilter(request="")) + handler.addFilter(LoggingContextFilter()) logger = self.get_logger(handler) with LoggingContext() as context_one: diff --git a/tests/test_utils/logging_setup.py b/tests/test_utils/logging_setup.py index fdfb840b6222..52ae5c57137f 100644 --- a/tests/test_utils/logging_setup.py +++ b/tests/test_utils/logging_setup.py @@ -48,7 +48,7 @@ def setup_logging(): handler = ToTwistedHandler() formatter = logging.Formatter(log_format) handler.setFormatter(formatter) - handler.addFilter(LoggingContextFilter(request="")) + handler.addFilter(LoggingContextFilter()) root_logger.addHandler(handler) log_level = os.environ.get("SYNAPSE_TEST_LOG_LEVEL", "ERROR") From 9cb2a8ae3c8b1decddee125c6dda71756f6df4d7 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 10 Dec 2020 09:28:41 -0500 Subject: [PATCH 3/6] Remove unnecessary request kwarg in tests. request is optional when making a LoggingContext, we should only be providing it for tests that need it. --- tests/handlers/test_federation.py | 6 +++--- tests/test_federation.py | 2 +- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/tests/handlers/test_federation.py b/tests/handlers/test_federation.py index d0452e1490cd..0b24b89a2ee7 100644 --- a/tests/handlers/test_federation.py +++ b/tests/handlers/test_federation.py @@ -126,7 +126,7 @@ def test_rejected_message_event_state(self): room_version, ) - with LoggingContext(request="send_rejected"): + with LoggingContext("send_rejected"): d = run_in_background(self.handler.on_receive_pdu, OTHER_SERVER, ev) self.get_success(d) @@ -178,7 +178,7 @@ def test_rejected_state_event_state(self): room_version, ) - with LoggingContext(request="send_rejected"): + with LoggingContext("send_rejected"): d = run_in_background(self.handler.on_receive_pdu, OTHER_SERVER, ev) self.get_success(d) @@ -198,7 +198,7 @@ def _build_and_send_join_event(self, other_server, other_user, room_id): # the auth code requires that a signature exists, but doesn't check that # signature... go figure. join_event.signatures[other_server] = {"x": "y"} - with LoggingContext(request="send_join"): + with LoggingContext("send_join"): d = run_in_background( self.handler.on_send_join_request, other_server, join_event ) diff --git a/tests/test_federation.py b/tests/test_federation.py index fa45f8b3b7e9..fc9aab32d063 100644 --- a/tests/test_federation.py +++ b/tests/test_federation.py @@ -134,7 +134,7 @@ async def post_json(destination, path, data, headers=None, timeout=0): } ) - with LoggingContext(request="lying_event"): + with LoggingContext(): failure = self.get_failure( self.handler.on_receive_pdu( "test.serv", lying_event, sent_to_us_directly=True From 7a7ea5fec0e7e485b07abe01f378d229d92e1056 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 10 Dec 2020 13:22:56 -0500 Subject: [PATCH 4/6] Remove the copy_to method from logging context. copy_to was being used in two different ways (the target of copy_to was completely different classes). This codes the simplified behavior into each location: * Copying from a parent to a child context during initialization. * Copying properties from a logging context to a log record. Note that with this change the "scope" is no longer copied to a log record. --- synapse/logging/context.py | 3 ++- tests/logging/test_terse_json.py | 2 -- 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index e808f92c2b70..a507a83e933c 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -548,7 +548,8 @@ def filter(self, record) -> Literal[True]: # we end up in a death spiral of infinite loops, so let's check, for # robustness' sake. if context is not None: - context.copy_to(record) + # Logging is interested in the request. + record.request = context.request return True diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index 576aeb35ec66..e391756592f2 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -132,9 +132,7 @@ def test_with_context(self): "level", "namespace", "request", - "scope", ] self.assertCountEqual(log.keys(), expected_log_keys) self.assertEqual(log["log"], "Hello there, wally!") self.assertEqual(log["request"], "test") - self.assertIsNone(log["scope"]) From a6a3629cbadc2affa3d29ad13e19a735ec60dc41 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Mon, 14 Dec 2020 09:29:11 -0500 Subject: [PATCH 5/6] Pass in request to the log context constructor. Simplify code by passing in request during initialization instead of after the object has been created. --- synapse/http/site.py | 3 +-- synapse/metrics/background_process_metrics.py | 7 +++---- synapse/replication/tcp/protocol.py | 3 +-- tests/logging/test_terse_json.py | 3 +-- 4 files changed, 6 insertions(+), 10 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index 5f0581dc3fac..5a5790831b0a 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -128,8 +128,7 @@ def render(self, resrc): # create a LogContext for this request request_id = self.get_request_id() - logcontext = self.logcontext = LoggingContext(request_id) - logcontext.request = request_id + self.logcontext = LoggingContext(request_id, request=request_id) # override the Server header which is set by twisted self.setHeader("Server", self.site.server_version_string) diff --git a/synapse/metrics/background_process_metrics.py b/synapse/metrics/background_process_metrics.py index 76b7decf260d..70e0fa45d9d1 100644 --- a/synapse/metrics/background_process_metrics.py +++ b/synapse/metrics/background_process_metrics.py @@ -199,8 +199,7 @@ async def run(): _background_process_start_count.labels(desc).inc() _background_process_in_flight_count.labels(desc).inc() - with BackgroundProcessLoggingContext(desc) as context: - context.request = "%s-%i" % (desc, count) + with BackgroundProcessLoggingContext(desc, "%s-%i" % (desc, count)) as context: try: ctx = noop_context_manager() if bg_start_span: @@ -244,8 +243,8 @@ class BackgroundProcessLoggingContext(LoggingContext): __slots__ = ["_proc"] - def __init__(self, name: str): - super().__init__(name) + def __init__(self, name: str, request: Optional[str] = None): + super().__init__(name, request=request) self._proc = _BackgroundProcess(name, self) diff --git a/synapse/replication/tcp/protocol.py b/synapse/replication/tcp/protocol.py index a509e599c20e..804da994eab3 100644 --- a/synapse/replication/tcp/protocol.py +++ b/synapse/replication/tcp/protocol.py @@ -172,8 +172,7 @@ def __init__(self, clock: Clock, handler: "ReplicationCommandHandler"): # a logcontext which we use for processing incoming commands. We declare it as a # background process so that the CPU stats get reported to prometheus. ctx_name = "replication-conn-%s" % self.conn_id - self._logging_context = BackgroundProcessLoggingContext(ctx_name) - self._logging_context.request = ctx_name + self._logging_context = BackgroundProcessLoggingContext(ctx_name, ctx_name) def connectionMade(self): logger.info("[%s] Connection established", self.id()) diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index e391756592f2..48a74e2eee75 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -120,8 +120,7 @@ def test_with_context(self): handler.addFilter(LoggingContextFilter()) logger = self.get_logger(handler) - with LoggingContext() as context_one: - context_one.request = "test" + with LoggingContext(request="test"): logger.info("Hello there, %s!", "wally") log = self.get_log_line() From 911064c464bd12065d61e3cbe98f9afeffe322e7 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Mon, 14 Dec 2020 09:36:44 -0500 Subject: [PATCH 6/6] Add newsfragment. --- changelog.d/8916.misc | 2 +- changelog.d/8935.misc | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) create mode 100644 changelog.d/8935.misc diff --git a/changelog.d/8916.misc b/changelog.d/8916.misc index c71ef480e6cc..bf94135fd5b4 100644 --- a/changelog.d/8916.misc +++ b/changelog.d/8916.misc @@ -1 +1 @@ -Improve structured logging tests. +Various clean-ups to the structured logging and logging context code. diff --git a/changelog.d/8935.misc b/changelog.d/8935.misc new file mode 100644 index 000000000000..bf94135fd5b4 --- /dev/null +++ b/changelog.d/8935.misc @@ -0,0 +1 @@ +Various clean-ups to the structured logging and logging context code.