From e3ae0e6fa25dcb5e1bc70cb1fb9462eae733e825 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 10 Dec 2020 13:42:34 -0500 Subject: [PATCH 01/12] Rename request -> request_id on LoggingContext. --- synapse/http/site.py | 2 +- synapse/logging/context.py | 41 +++++++++++-------- synapse/metrics/background_process_metrics.py | 6 +-- tests/crypto/test_keyring.py | 12 +++--- tests/logging/test_terse_json.py | 2 +- tests/unittest.py | 2 +- tests/util/caches/test_descriptors.py | 6 +-- tests/util/test_logcontext.py | 22 +++++----- 8 files changed, 49 insertions(+), 44 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index 47754aff43ca..cb5817c16a2e 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -132,7 +132,7 @@ def render(self, resrc): # create a LogContext for this request request_id = self.get_request_id() - self.logcontext = LoggingContext(request_id, request=request_id) + self.logcontext = LoggingContext(request_id, request_id=request_id) # override the Server header which is set by twisted self.setHeader("Server", self.site.server_version_string) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 1a7ea4fa9629..9e5ea035764a 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -187,13 +187,13 @@ def __sub__(self, other: "ContextResourceUsage") -> "ContextResourceUsage": class _Sentinel: """Sentinel to represent the root context""" - __slots__ = ["previous_context", "finished", "request", "scope", "tag"] + __slots__ = ["previous_context", "finished", "request_id", "scope", "tag"] def __init__(self) -> None: # Minimal set for compatibility with LoggingContext self.previous_context = None self.finished = False - self.request = None + self.request_id = None self.scope = None self.tag = None @@ -247,7 +247,7 @@ class LoggingContext: "usage_start", "main_thread", "finished", - "request", + "request_id", "tag", "scope", ] @@ -256,7 +256,7 @@ def __init__( self, name: Optional[str] = None, parent_context: "Optional[LoggingContext]" = None, - request: Optional[str] = None, + request_id: Optional[str] = None, ) -> None: self.previous_context = current_context() self.name = name @@ -269,7 +269,7 @@ def __init__( self.usage_start = None # type: Optional[resource._RUsage] self.main_thread = get_thread_id() - self.request = None + self.request_id = None self.tag = "" self.scope = None # type: Optional[_LogContextScope] @@ -281,15 +281,19 @@ def __init__( self.parent_context = parent_context if self.parent_context is not None: - self.parent_context.copy_to(self) + # we track the current request_id + self.request_id = self.parent_context.request_id - if request is not None: - # the request param overrides the request from the parent context - self.request = request + # we also track the current scope: + self.scope = self.parent_context.scope + + if request_id is not None: + # the request_id param overrides the request_id from the parent context + self.request_id = request_id def __str__(self) -> str: - if self.request: - return str(self.request) + if self.request_id: + return self.request_id return "%s@%x" % (self.name, id(self)) @classmethod @@ -556,8 +560,9 @@ def filter(self, record: logging.LogRecord) -> Literal[True]: # we end up in a death spiral of infinite loops, so let's check, for # robustness' sake. if context is not None: - # Logging is interested in the request. - record.request = context.request # type: ignore + # Logging is interested in the request ID. Note that for backwards + # compatibility this is stored as the "request" on the record. + record.request = context.request_id # type: ignore return True @@ -630,8 +635,8 @@ def set_current_context(context: LoggingContextOrSentinel) -> LoggingContextOrSe def nested_logging_context(suffix: str) -> LoggingContext: """Creates a new logging context as a child of another. - The nested logging context will have a 'request' made up of the parent context's - request, plus the given suffix. + The nested logging context will have a 'request_id' made up of the parent context's + request_id, plus the given suffix. CPU/db usage stats will be added to the parent context's on exit. @@ -641,7 +646,7 @@ def nested_logging_context(suffix: str) -> LoggingContext: # ... do stuff Args: - suffix: suffix to add to the parent context's 'request'. + suffix: suffix to add to the parent context's 'request_id'. Returns: LoggingContext: new logging context. @@ -656,8 +661,8 @@ def nested_logging_context(suffix: str) -> LoggingContext: else: assert isinstance(curr_context, LoggingContext) parent_context = curr_context - prefix = str(parent_context.request) - return LoggingContext(parent_context=parent_context, request=prefix + "-" + suffix) + prefix = str(parent_context.request_id) + return LoggingContext(parent_context=parent_context, request_id=prefix + "-" + suffix) def preserve_fn(f): diff --git a/synapse/metrics/background_process_metrics.py b/synapse/metrics/background_process_metrics.py index b56986d8e753..a2106e9e540c 100644 --- a/synapse/metrics/background_process_metrics.py +++ b/synapse/metrics/background_process_metrics.py @@ -203,7 +203,7 @@ async def run(): try: ctx = noop_context_manager() if bg_start_span: - ctx = start_active_span(desc, tags={"request_id": context.request}) + ctx = start_active_span(desc, tags={"request_id": context.request_id}) with ctx: return await maybe_awaitable(func(*args, **kwargs)) except Exception: @@ -244,8 +244,8 @@ class BackgroundProcessLoggingContext(LoggingContext): __slots__ = ["_proc"] - def __init__(self, name: str, request: Optional[str] = None): - super().__init__(name, request=request) + def __init__(self, name: str, request_id: Optional[str] = None): + super().__init__(name, request_id=request_id) self._proc = _BackgroundProcess(name, self) diff --git a/tests/crypto/test_keyring.py b/tests/crypto/test_keyring.py index 30fcc4c1bfcc..53697c95d91a 100644 --- a/tests/crypto/test_keyring.py +++ b/tests/crypto/test_keyring.py @@ -71,7 +71,7 @@ def sign_response(self, res): @logcontext_clean class KeyringTestCase(unittest.HomeserverTestCase): def check_context(self, val, expected): - self.assertEquals(getattr(current_context(), "request", None), expected) + self.assertEquals(getattr(current_context(), "request_id", None), expected) return val def test_verify_json_objects_for_server_awaits_previous_requests(self): @@ -89,7 +89,7 @@ def test_verify_json_objects_for_server_awaits_previous_requests(self): first_lookup_deferred = Deferred() async def first_lookup_fetch(keys_to_fetch): - self.assertEquals(current_context().request, "context_11") + self.assertEquals(current_context().request_id, "context_11") self.assertEqual(keys_to_fetch, {"server10": {get_key_id(key1): 0}}) await make_deferred_yieldable(first_lookup_deferred) @@ -103,7 +103,7 @@ async def first_lookup_fetch(keys_to_fetch): async def first_lookup(): with LoggingContext("context_11") as context_11: - context_11.request = "context_11" + context_11.request_id = "context_11" res_deferreds = kr.verify_json_objects_for_server( [("server10", json1, 0, "test10"), ("server11", {}, 0, "test11")] @@ -130,7 +130,7 @@ async def first_lookup(): # should block rather than start a second call async def second_lookup_fetch(keys_to_fetch): - self.assertEquals(current_context().request, "context_12") + self.assertEquals(current_context().request_id, "context_12") return { "server10": { get_key_id(key1): FetchKeyResult(get_verify_key(key1), 100) @@ -143,7 +143,7 @@ async def second_lookup_fetch(keys_to_fetch): async def second_lookup(): with LoggingContext("context_12") as context_12: - context_12.request = "context_12" + context_12.request_id = "context_12" res_deferreds_2 = kr.verify_json_objects_for_server( [("server10", json1, 0, "test")] @@ -592,7 +592,7 @@ def run_in_context(f, *args, **kwargs): with LoggingContext("testctx") as ctx: # we set the "request" prop to make it easier to follow what's going on in the # logs. - ctx.request = "testctx" + ctx.request_id = "testctx" rv = yield f(*args, **kwargs) return rv diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index 48a74e2eee75..b6caa65251b2 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -120,7 +120,7 @@ def test_with_context(self): handler.addFilter(LoggingContextFilter()) logger = self.get_logger(handler) - with LoggingContext(request="test"): + with LoggingContext(request_id="test"): logger.info("Hello there, %s!", "wally") log = self.get_log_line() diff --git a/tests/unittest.py b/tests/unittest.py index 58a4daa1ec86..2ee6ee3217fa 100644 --- a/tests/unittest.py +++ b/tests/unittest.py @@ -471,7 +471,7 @@ def setup_test_homeserver(self, *args, **kwargs): kwargs["config"] = config_obj async def run_bg_updates(): - with LoggingContext("run_bg_updates", request="run_bg_updates-1"): + with LoggingContext("run_bg_updates", request_id="run_bg_updates-1"): while not await stor.db_pool.updates.has_completed_background_updates(): await stor.db_pool.updates.do_next_background_update(1) diff --git a/tests/util/caches/test_descriptors.py b/tests/util/caches/test_descriptors.py index afb11b9caf2d..ee844a8225c2 100644 --- a/tests/util/caches/test_descriptors.py +++ b/tests/util/caches/test_descriptors.py @@ -661,14 +661,14 @@ def fn(self, arg1, arg2): @descriptors.cachedList("fn", "args1") async def list_fn(self, args1, arg2): - assert current_context().request == "c1" + assert current_context().request_id == "c1" # we want this to behave like an asynchronous function await run_on_reactor() - assert current_context().request == "c1" + assert current_context().request_id == "c1" return self.mock(args1, arg2) with LoggingContext() as c1: - c1.request = "c1" + c1.request_id = "c1" obj = Cls() obj.mock.return_value = {10: "fish", 20: "chips"} d1 = obj.list_fn([10, 20], 2) diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index 58ee918f6533..ab369971cdd4 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -17,11 +17,11 @@ class LoggingContextTestCase(unittest.TestCase): def _check_test_key(self, value): - self.assertEquals(current_context().request, value) + self.assertEquals(current_context().request_id, value) def test_with_context(self): with LoggingContext() as context_one: - context_one.request = "test" + context_one.request_id = "test" self._check_test_key("test") @defer.inlineCallbacks @@ -31,14 +31,14 @@ def test_sleep(self): @defer.inlineCallbacks def competing_callback(): with LoggingContext() as competing_context: - competing_context.request = "competing" + competing_context.request_id = "competing" yield clock.sleep(0) self._check_test_key("competing") reactor.callLater(0, competing_callback) with LoggingContext() as context_one: - context_one.request = "one" + context_one.request_id = "one" yield clock.sleep(0) self._check_test_key("one") @@ -48,7 +48,7 @@ def _test_run_in_background(self, function): callback_completed = [False] with LoggingContext() as context_one: - context_one.request = "one" + context_one.request_id = "one" # fire off function, but don't wait on it. d2 = run_in_background(function) @@ -134,7 +134,7 @@ def blocking_function(): sentinel_context = current_context() with LoggingContext() as context_one: - context_one.request = "one" + context_one.request_id = "one" d1 = make_deferred_yieldable(blocking_function()) # make sure that the context was reset by make_deferred_yieldable @@ -150,7 +150,7 @@ def test_make_deferred_yieldable_with_chained_deferreds(self): sentinel_context = current_context() with LoggingContext() as context_one: - context_one.request = "one" + context_one.request_id = "one" d1 = make_deferred_yieldable(_chained_deferred_function()) # make sure that the context was reset by make_deferred_yieldable @@ -167,7 +167,7 @@ def test_make_deferred_yieldable_on_non_deferred(self): argument isn't actually a deferred""" with LoggingContext() as context_one: - context_one.request = "one" + context_one.request_id = "one" d1 = make_deferred_yieldable("bum") self._check_test_key("one") @@ -177,9 +177,9 @@ def test_make_deferred_yieldable_on_non_deferred(self): self._check_test_key("one") def test_nested_logging_context(self): - with LoggingContext(request="foo"): + with LoggingContext(request_id="foo"): nested_context = nested_logging_context(suffix="bar") - self.assertEqual(nested_context.request, "foo-bar") + self.assertEqual(nested_context.request_id, "foo-bar") @defer.inlineCallbacks def test_make_deferred_yieldable_with_await(self): @@ -194,7 +194,7 @@ async def blocking_function(): sentinel_context = current_context() with LoggingContext() as context_one: - context_one.request = "one" + context_one.request_id = "one" d1 = make_deferred_yieldable(blocking_function()) # make sure that the context was reset by make_deferred_yieldable From 28275b320ecf8c028f04d5bf175887a234c622d2 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Fri, 19 Mar 2021 13:24:56 -0400 Subject: [PATCH 02/12] Use the request instead of just store the request ID. --- synapse/http/site.py | 5 ++- synapse/logging/context.py | 34 ++++++++------ synapse/metrics/background_process_metrics.py | 18 +++++--- synapse/replication/tcp/protocol.py | 5 ++- tests/crypto/test_keyring.py | 25 +++++------ tests/logging/test_terse_json.py | 44 +++++++++++++++++-- tests/unittest.py | 2 +- tests/util/caches/test_descriptors.py | 7 ++- tests/util/test_logcontext.py | 35 +++++---------- 9 files changed, 107 insertions(+), 68 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index cb5817c16a2e..6584e92950a9 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -132,7 +132,7 @@ def render(self, resrc): # create a LogContext for this request request_id = self.get_request_id() - self.logcontext = LoggingContext(request_id, request_id=request_id) + self.logcontext = LoggingContext(request_id, request=self) # override the Server header which is set by twisted self.setHeader("Server", self.site.server_version_string) @@ -334,6 +334,9 @@ def _finished_processing(self): except Exception as e: logger.warning("Failed to stop metrics: %r", e) + # Break the cycle between SynapseRequest and LoggingContext. + self.logcontext = None + def _should_log_request(self) -> bool: """Whether we should log at INFO that we processed the request.""" if self.path == b"/health": diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 9e5ea035764a..1bce8ed45c88 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -22,7 +22,6 @@ See doc/log_contexts.rst for details on how this works. """ - import inspect import logging import threading @@ -35,6 +34,7 @@ from twisted.internet import defer, threads if TYPE_CHECKING: + from synapse.http.site import SynapseRequest from synapse.logging.scopecontextmanager import _LogContextScope logger = logging.getLogger(__name__) @@ -187,13 +187,13 @@ def __sub__(self, other: "ContextResourceUsage") -> "ContextResourceUsage": class _Sentinel: """Sentinel to represent the root context""" - __slots__ = ["previous_context", "finished", "request_id", "scope", "tag"] + __slots__ = ["previous_context", "finished", "request", "scope", "tag"] def __init__(self) -> None: # Minimal set for compatibility with LoggingContext self.previous_context = None self.finished = False - self.request_id = None + self.request = None self.scope = None self.tag = None @@ -247,7 +247,7 @@ class LoggingContext: "usage_start", "main_thread", "finished", - "request_id", + "request", "tag", "scope", ] @@ -256,7 +256,7 @@ def __init__( self, name: Optional[str] = None, parent_context: "Optional[LoggingContext]" = None, - request_id: Optional[str] = None, + request: "Optional[SynapseRequest]" = None, ) -> None: self.previous_context = current_context() self.name = name @@ -269,7 +269,7 @@ def __init__( self.usage_start = None # type: Optional[resource._RUsage] self.main_thread = get_thread_id() - self.request_id = None + self.request = None self.tag = "" self.scope = None # type: Optional[_LogContextScope] @@ -282,18 +282,18 @@ def __init__( if self.parent_context is not None: # we track the current request_id - self.request_id = self.parent_context.request_id + self.request = self.parent_context.request # we also track the current scope: self.scope = self.parent_context.scope - if request_id is not None: + if request is not None: # the request_id param overrides the request_id from the parent context - self.request_id = request_id + self.request = request def __str__(self) -> str: - if self.request_id: - return self.request_id + if self.request: + return self.request.get_request_id() return "%s@%x" % (self.name, id(self)) @classmethod @@ -562,7 +562,7 @@ def filter(self, record: logging.LogRecord) -> Literal[True]: if context is not None: # Logging is interested in the request ID. Note that for backwards # compatibility this is stored as the "request" on the record. - record.request = context.request_id # type: ignore + record.request = str(context) # type: ignore return True @@ -658,11 +658,17 @@ def nested_logging_context(suffix: str) -> LoggingContext: ) parent_context = None prefix = "" + request = None else: assert isinstance(curr_context, LoggingContext) parent_context = curr_context - prefix = str(parent_context.request_id) - return LoggingContext(parent_context=parent_context, request_id=prefix + "-" + suffix) + prefix = str(parent_context.name) + request = parent_context.request + return LoggingContext( + prefix + "-" + suffix, + parent_context=parent_context, + request=request, + ) def preserve_fn(f): diff --git a/synapse/metrics/background_process_metrics.py b/synapse/metrics/background_process_metrics.py index a2106e9e540c..e8a9096c039e 100644 --- a/synapse/metrics/background_process_metrics.py +++ b/synapse/metrics/background_process_metrics.py @@ -16,7 +16,7 @@ import logging import threading from functools import wraps -from typing import TYPE_CHECKING, Dict, Optional, Set +from typing import TYPE_CHECKING, Dict, Optional, Set, Union from prometheus_client.core import REGISTRY, Counter, Gauge @@ -199,11 +199,11 @@ async def run(): _background_process_start_count.labels(desc).inc() _background_process_in_flight_count.labels(desc).inc() - with BackgroundProcessLoggingContext(desc, "%s-%i" % (desc, count)) as context: + with BackgroundProcessLoggingContext(desc, count) as context: try: ctx = noop_context_manager() if bg_start_span: - ctx = start_active_span(desc, tags={"request_id": context.request_id}) + ctx = start_active_span(desc, tags={"request_id": str(context)}) with ctx: return await maybe_awaitable(func(*args, **kwargs)) except Exception: @@ -242,13 +242,19 @@ class BackgroundProcessLoggingContext(LoggingContext): processes. """ - __slots__ = ["_proc"] + __slots__ = ["_id", "_proc"] - def __init__(self, name: str, request_id: Optional[str] = None): - super().__init__(name, request_id=request_id) + def __init__(self, name: str, id: Optional[Union[int, str]] = None): + super().__init__(name) + self._id = id self._proc = _BackgroundProcess(name, self) + def __str__(self) -> str: + if self._id is not None: + return "%s-%s" % (self.name, self._id) + return "%s@%x" % (self.name, id(self)) + def start(self, rusage: "Optional[resource._RUsage]"): """Log context has started running (again).""" diff --git a/synapse/replication/tcp/protocol.py b/synapse/replication/tcp/protocol.py index 825900f64c1d..9c5233d3af60 100644 --- a/synapse/replication/tcp/protocol.py +++ b/synapse/replication/tcp/protocol.py @@ -184,8 +184,9 @@ 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, ctx_name) + self._logging_context = BackgroundProcessLoggingContext( + "replication-conn", self.conn_id + ) def connectionMade(self): logger.info("[%s] Connection established", self.id()) diff --git a/tests/crypto/test_keyring.py b/tests/crypto/test_keyring.py index 53697c95d91a..946482b7e706 100644 --- a/tests/crypto/test_keyring.py +++ b/tests/crypto/test_keyring.py @@ -16,6 +16,7 @@ from mock import Mock +import attr import canonicaljson import signedjson.key import signedjson.sign @@ -68,10 +69,15 @@ def sign_response(self, res): signedjson.sign.sign_json(res, self.server_name, self.key) +@attr.s(slots=True) +class FakeRequest: + id = attr.ib() + + @logcontext_clean class KeyringTestCase(unittest.HomeserverTestCase): def check_context(self, val, expected): - self.assertEquals(getattr(current_context(), "request_id", None), expected) + self.assertEquals(getattr(current_context(), "request", None), expected) return val def test_verify_json_objects_for_server_awaits_previous_requests(self): @@ -89,7 +95,7 @@ def test_verify_json_objects_for_server_awaits_previous_requests(self): first_lookup_deferred = Deferred() async def first_lookup_fetch(keys_to_fetch): - self.assertEquals(current_context().request_id, "context_11") + self.assertEquals(current_context().request.id, "context_11") self.assertEqual(keys_to_fetch, {"server10": {get_key_id(key1): 0}}) await make_deferred_yieldable(first_lookup_deferred) @@ -102,9 +108,7 @@ async def first_lookup_fetch(keys_to_fetch): mock_fetcher.get_keys.side_effect = first_lookup_fetch async def first_lookup(): - with LoggingContext("context_11") as context_11: - context_11.request_id = "context_11" - + with LoggingContext("context_11", request=FakeRequest("context_11")): res_deferreds = kr.verify_json_objects_for_server( [("server10", json1, 0, "test10"), ("server11", {}, 0, "test11")] ) @@ -130,7 +134,7 @@ async def first_lookup(): # should block rather than start a second call async def second_lookup_fetch(keys_to_fetch): - self.assertEquals(current_context().request_id, "context_12") + self.assertEquals(current_context().request.id, "context_12") return { "server10": { get_key_id(key1): FetchKeyResult(get_verify_key(key1), 100) @@ -142,9 +146,7 @@ async def second_lookup_fetch(keys_to_fetch): second_lookup_state = [0] async def second_lookup(): - with LoggingContext("context_12") as context_12: - context_12.request_id = "context_12" - + with LoggingContext("context_12", request=FakeRequest("context_12")): res_deferreds_2 = kr.verify_json_objects_for_server( [("server10", json1, 0, "test")] ) @@ -589,10 +591,7 @@ def get_key_id(key): @defer.inlineCallbacks def run_in_context(f, *args, **kwargs): - with LoggingContext("testctx") as ctx: - # we set the "request" prop to make it easier to follow what's going on in the - # logs. - ctx.request_id = "testctx" + with LoggingContext("testctx"): rv = yield f(*args, **kwargs) return rv diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index b6caa65251b2..0ecff16a52da 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -15,12 +15,16 @@ import json import logging -from io import StringIO +from io import BytesIO, StringIO +from mock import Mock + +from synapse.http.site import SynapseRequest from synapse.logging._terse_json import JsonFormatter, TerseJsonFormatter from synapse.logging.context import LoggingContext, LoggingContextFilter from tests.logging import LoggerCleanupMixin +from tests.server import FakeChannel from tests.unittest import TestCase @@ -120,7 +124,41 @@ def test_with_context(self): handler.addFilter(LoggingContextFilter()) logger = self.get_logger(handler) - with LoggingContext(request_id="test"): + with LoggingContext("name"): + logger.info("Hello there, %s!", "wally") + + log = self.get_log_line() + + # The terse logger should give us these keys. + expected_log_keys = [ + "log", + "level", + "namespace", + "request", + ] + self.assertCountEqual(log.keys(), expected_log_keys) + self.assertEqual(log["log"], "Hello there, wally!") + self.assertTrue(log["request"].startswith("name@")) + + def test_with_request_context(self): + """ + Information from the logging context request should be added to the JSON response. + """ + handler = logging.StreamHandler(self.output) + handler.setFormatter(JsonFormatter()) + handler.addFilter(LoggingContextFilter()) + logger = self.get_logger(handler) + + # A full request isn't needed here. + site = Mock(spec=["site_tag"]) + site.site_tag = "test-site" + request = SynapseRequest(FakeChannel(site, None)) + # Call requestReceived to finish instantiating the object. + request.content = BytesIO() + request.process = Mock() + request.requestReceived(b"POST", b"/_matrix/client/versions", b"1.1") + + with LoggingContext(request=request): logger.info("Hello there, %s!", "wally") log = self.get_log_line() @@ -134,4 +172,4 @@ def test_with_context(self): ] self.assertCountEqual(log.keys(), expected_log_keys) self.assertEqual(log["log"], "Hello there, wally!") - self.assertEqual(log["request"], "test") + self.assertTrue(log["request"].startswith("POST-")) diff --git a/tests/unittest.py b/tests/unittest.py index 2ee6ee3217fa..57b6a395c791 100644 --- a/tests/unittest.py +++ b/tests/unittest.py @@ -471,7 +471,7 @@ def setup_test_homeserver(self, *args, **kwargs): kwargs["config"] = config_obj async def run_bg_updates(): - with LoggingContext("run_bg_updates", request_id="run_bg_updates-1"): + with LoggingContext("run_bg_updates"): while not await stor.db_pool.updates.has_completed_background_updates(): await stor.db_pool.updates.do_next_background_update(1) diff --git a/tests/util/caches/test_descriptors.py b/tests/util/caches/test_descriptors.py index ee844a8225c2..e434e21aeee6 100644 --- a/tests/util/caches/test_descriptors.py +++ b/tests/util/caches/test_descriptors.py @@ -661,14 +661,13 @@ def fn(self, arg1, arg2): @descriptors.cachedList("fn", "args1") async def list_fn(self, args1, arg2): - assert current_context().request_id == "c1" + assert current_context().name == "c1" # we want this to behave like an asynchronous function await run_on_reactor() - assert current_context().request_id == "c1" + assert current_context().name == "c1" return self.mock(args1, arg2) - with LoggingContext() as c1: - c1.request_id = "c1" + with LoggingContext("c1") as c1: obj = Cls() obj.mock.return_value = {10: "fish", 20: "chips"} d1 = obj.list_fn([10, 20], 2) diff --git a/tests/util/test_logcontext.py b/tests/util/test_logcontext.py index ab369971cdd4..5d9c4665aa58 100644 --- a/tests/util/test_logcontext.py +++ b/tests/util/test_logcontext.py @@ -17,11 +17,10 @@ class LoggingContextTestCase(unittest.TestCase): def _check_test_key(self, value): - self.assertEquals(current_context().request_id, value) + self.assertEquals(current_context().name, value) def test_with_context(self): - with LoggingContext() as context_one: - context_one.request_id = "test" + with LoggingContext("test"): self._check_test_key("test") @defer.inlineCallbacks @@ -30,15 +29,13 @@ def test_sleep(self): @defer.inlineCallbacks def competing_callback(): - with LoggingContext() as competing_context: - competing_context.request_id = "competing" + with LoggingContext("competing"): yield clock.sleep(0) self._check_test_key("competing") reactor.callLater(0, competing_callback) - with LoggingContext() as context_one: - context_one.request_id = "one" + with LoggingContext("one"): yield clock.sleep(0) self._check_test_key("one") @@ -47,9 +44,7 @@ def _test_run_in_background(self, function): callback_completed = [False] - with LoggingContext() as context_one: - context_one.request_id = "one" - + with LoggingContext("one"): # fire off function, but don't wait on it. d2 = run_in_background(function) @@ -133,9 +128,7 @@ def blocking_function(): sentinel_context = current_context() - with LoggingContext() as context_one: - context_one.request_id = "one" - + with LoggingContext("one"): d1 = make_deferred_yieldable(blocking_function()) # make sure that the context was reset by make_deferred_yieldable self.assertIs(current_context(), sentinel_context) @@ -149,9 +142,7 @@ def blocking_function(): def test_make_deferred_yieldable_with_chained_deferreds(self): sentinel_context = current_context() - with LoggingContext() as context_one: - context_one.request_id = "one" - + with LoggingContext("one"): d1 = make_deferred_yieldable(_chained_deferred_function()) # make sure that the context was reset by make_deferred_yieldable self.assertIs(current_context(), sentinel_context) @@ -166,9 +157,7 @@ def test_make_deferred_yieldable_on_non_deferred(self): """Check that make_deferred_yieldable does the right thing when its argument isn't actually a deferred""" - with LoggingContext() as context_one: - context_one.request_id = "one" - + with LoggingContext("one"): d1 = make_deferred_yieldable("bum") self._check_test_key("one") @@ -177,9 +166,9 @@ def test_make_deferred_yieldable_on_non_deferred(self): self._check_test_key("one") def test_nested_logging_context(self): - with LoggingContext(request_id="foo"): + with LoggingContext("foo"): nested_context = nested_logging_context(suffix="bar") - self.assertEqual(nested_context.request_id, "foo-bar") + self.assertEqual(nested_context.name, "foo-bar") @defer.inlineCallbacks def test_make_deferred_yieldable_with_await(self): @@ -193,9 +182,7 @@ async def blocking_function(): sentinel_context = current_context() - with LoggingContext() as context_one: - context_one.request_id = "one" - + with LoggingContext("one"): d1 = make_deferred_yieldable(blocking_function()) # make sure that the context was reset by make_deferred_yieldable self.assertIs(current_context(), sentinel_context) From dab36c23aa14358ac976c6ca94d774a02cab6173 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 10 Dec 2020 14:20:58 -0500 Subject: [PATCH 03/12] Add additional request information to structured logs. --- synapse/http/site.py | 24 +++++++++++++++++++++++- synapse/logging/context.py | 16 ++++++++++++++++ tests/logging/test_terse_json.py | 17 +++++++++++++++-- 3 files changed, 54 insertions(+), 3 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index 6584e92950a9..40f9b4acd354 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -126,6 +126,28 @@ def get_method(self) -> str: return self.method.decode("ascii") return method + def get_authenticated_entity(self) -> Optional[str]: + # Convert the requester into a string that we can log + if isinstance(self.requester, str): + return self.requester + elif isinstance(self.requester, Requester): + authenticated_entity = self.requester.authenticated_entity + + # If this is a request where the target user doesn't match the user who + # authenticated (e.g. and admin is puppetting a user) then we log both. + if self.requester.user.to_string() != authenticated_entity: + return "{},{}".format( + authenticated_entity, + self.requester.user.to_string(), + ) + return authenticated_entity + elif self.requester is not None: + # This shouldn't happen, but we log it so we don't lose information + # and can see that we're doing something wrong. + return repr(self.requester) # type: ignore[unreachable] + + return None + def render(self, resrc): # this is called once a Resource has been found to serve the request; in our # case the Resource in question will normally be a JsonResource. @@ -312,7 +334,7 @@ def _finished_processing(self): ' %sB %s "%s %s %s" "%s" [%d dbevts]', self.getClientIP(), self.site.site_tag, - authenticated_entity, + self.get_authenticated_entity(), processing_time, response_send_time, usage.ru_utime, diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 1bce8ed45c88..b15932fb0931 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -564,6 +564,22 @@ def filter(self, record: logging.LogRecord) -> Literal[True]: # compatibility this is stored as the "request" on the record. record.request = str(context) # type: ignore + # Add some data from the HTTP request. + request = context.request + if request is None: + return True + + # Avoid a circular import. + from synapse.http import get_request_user_agent + + record.ip_address = request.getClientIP() # type: ignore + record.site_tag = request.site.site_tag # type: ignore + record.authenticated_entity = request.get_authenticated_entity() # type: ignore + record.method = request.get_method() # type: ignore + record.url = request.get_redacted_uri() # type: ignore + record.protocol = request.clientproto.decode("ascii", errors="replace") # type: ignore + record.user_agent = get_request_user_agent(request) # type: ignore + return True diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index 0ecff16a52da..cc91f7ee2dd2 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -12,7 +12,6 @@ # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. - import json import logging from io import BytesIO, StringIO @@ -163,13 +162,27 @@ def test_with_request_context(self): log = self.get_log_line() - # The terse logger should give us these keys. + # The terse logger includes additional request information, if possible. expected_log_keys = [ "log", "level", "namespace", "request", + "ip_address", + "site_tag", + "authenticated_entity", + "method", + "url", + "protocol", + "user_agent", ] self.assertCountEqual(log.keys(), expected_log_keys) self.assertEqual(log["log"], "Hello there, wally!") self.assertTrue(log["request"].startswith("POST-")) + self.assertEqual(log["ip_address"], "127.0.0.1") + self.assertEqual(log["site_tag"], "test-site") + self.assertIsNone(log["authenticated_entity"]) + self.assertEqual(log["method"], "POST") + self.assertEqual(log["url"], "/_matrix/client/versions") + self.assertEqual(log["protocol"], "1.1") + self.assertEqual(log["user_agent"], "") From 269b28fe5a35269d83122ce3536969b659fcddc7 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Fri, 19 Mar 2021 14:09:15 -0400 Subject: [PATCH 04/12] Newsfragment --- changelog.d/9654.feature | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/9654.feature diff --git a/changelog.d/9654.feature b/changelog.d/9654.feature new file mode 100644 index 000000000000..a54c96cf19d1 --- /dev/null +++ b/changelog.d/9654.feature @@ -0,0 +1 @@ +Include request information in structured logging output. From 41e4de141aa4bb1548ead24b2edbad6adbca1665 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Tue, 23 Mar 2021 09:08:35 -0400 Subject: [PATCH 05/12] Return the requester and authenticated entity separately. --- synapse/http/site.py | 61 ++++++++++++++++---------------- synapse/logging/context.py | 2 +- tests/logging/test_terse_json.py | 2 ++ 3 files changed, 33 insertions(+), 32 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index 40f9b4acd354..a77a64a6a41d 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -14,7 +14,7 @@ import contextlib import logging import time -from typing import Optional, Type, Union +from typing import Optional, Tuple, Type, Union import attr from zope.interface import implementer @@ -126,27 +126,38 @@ def get_method(self) -> str: return self.method.decode("ascii") return method - def get_authenticated_entity(self) -> Optional[str]: + def get_authenticated_entity(self) -> Tuple[Optional[str], Optional[str]]: + """ + Get the "authenticated" entity of the request, which might be the user + performing the action, or a user being puppeted by a server admin. + + Returns: + A tuple: + The first item is a string representing the user making the request. + + The second item is a string or None representing the user who + authenticated when making this request. See + Requester.authenticated_entity. + """ # Convert the requester into a string that we can log if isinstance(self.requester, str): - return self.requester + return self.requester, None elif isinstance(self.requester, Requester): + requester = self.requester.user.to_string() authenticated_entity = self.requester.authenticated_entity # If this is a request where the target user doesn't match the user who - # authenticated (e.g. and admin is puppetting a user) then we log both. + # authenticated (e.g. and admin is puppetting a user) then we return both. if self.requester.user.to_string() != authenticated_entity: - return "{},{}".format( - authenticated_entity, - self.requester.user.to_string(), - ) - return authenticated_entity + return requester, authenticated_entity + + return requester, None elif self.requester is not None: # This shouldn't happen, but we log it so we don't lose information # and can see that we're doing something wrong. - return repr(self.requester) # type: ignore[unreachable] + return repr(self.requester), None # type: ignore[unreachable] - return None + return None, None def render(self, resrc): # this is called once a Resource has been found to serve the request; in our @@ -299,25 +310,6 @@ def _finished_processing(self): # to the client (nb may be negative) response_send_time = self.finish_time - self._processing_finished_time - # Convert the requester into a string that we can log - authenticated_entity = None - if isinstance(self.requester, str): - authenticated_entity = self.requester - elif isinstance(self.requester, Requester): - authenticated_entity = self.requester.authenticated_entity - - # If this is a request where the target user doesn't match the user who - # authenticated (e.g. and admin is puppetting a user) then we log both. - if self.requester.user.to_string() != authenticated_entity: - authenticated_entity = "{},{}".format( - authenticated_entity, - self.requester.user.to_string(), - ) - elif self.requester is not None: - # This shouldn't happen, but we log it so we don't lose information - # and can see that we're doing something wrong. - authenticated_entity = repr(self.requester) # type: ignore[unreachable] - user_agent = get_request_user_agent(self, "-") code = str(self.code) @@ -327,6 +319,13 @@ def _finished_processing(self): code += "!" log_level = logging.INFO if self._should_log_request() else logging.DEBUG + + # If this is a request where the target user doesn't match the user who + # authenticated (e.g. and admin is puppetting a user) then we log both. + requester, authenticated_entity = self.get_authenticated_entity() + if authenticated_entity: + requester = "{}.{}".format(authenticated_entity, requester) + self.site.access_logger.log( log_level, "%s - %s - {%s}" @@ -334,7 +333,7 @@ def _finished_processing(self): ' %sB %s "%s %s %s" "%s" [%d dbevts]', self.getClientIP(), self.site.site_tag, - self.get_authenticated_entity(), + requester, processing_time, response_send_time, usage.ru_utime, diff --git a/synapse/logging/context.py b/synapse/logging/context.py index b15932fb0931..4d207077eed3 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -574,7 +574,7 @@ def filter(self, record: logging.LogRecord) -> Literal[True]: record.ip_address = request.getClientIP() # type: ignore record.site_tag = request.site.site_tag # type: ignore - record.authenticated_entity = request.get_authenticated_entity() # type: ignore + record.requester, record.authenticated_entity = request.get_authenticated_entity() # type: ignore record.method = request.get_method() # type: ignore record.url = request.get_redacted_uri() # type: ignore record.protocol = request.clientproto.decode("ascii", errors="replace") # type: ignore diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index cc91f7ee2dd2..296f3e3cdaa9 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -170,6 +170,7 @@ def test_with_request_context(self): "request", "ip_address", "site_tag", + "requester", "authenticated_entity", "method", "url", @@ -181,6 +182,7 @@ def test_with_request_context(self): self.assertTrue(log["request"].startswith("POST-")) self.assertEqual(log["ip_address"], "127.0.0.1") self.assertEqual(log["site_tag"], "test-site") + self.assertIsNone(log["requester"]) self.assertIsNone(log["authenticated_entity"]) self.assertEqual(log["method"], "POST") self.assertEqual(log["url"], "/_matrix/client/versions") From 49ee329368dc16543a2f15583e7aa84c9af9a12b Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 24 Mar 2021 08:06:35 -0400 Subject: [PATCH 06/12] Store request attributes in a separate object. --- synapse/http/site.py | 65 +++++++++++++++++++++++++------- synapse/logging/context.py | 59 ++++++++++++++++++++++------- tests/logging/test_terse_json.py | 21 ++++++++--- 3 files changed, 112 insertions(+), 33 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index a77a64a6a41d..d6f43caad170 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -26,7 +26,11 @@ from synapse.config.server import ListenerConfig from synapse.http import get_request_user_agent, redact_uri from synapse.http.request_metrics import RequestMetrics, requests_counter -from synapse.logging.context import LoggingContext, PreserveLoggingContext +from synapse.logging.context import ( + ContextRequest, + LoggingContext, + PreserveLoggingContext, +) from synapse.types import Requester logger = logging.getLogger(__name__) @@ -63,7 +67,7 @@ def __init__(self, channel, *args, **kw): # The requester, if authenticated. For federation requests this is the # server name, for client requests this is the Requester object. - self.requester = None # type: Optional[Union[Requester, str]] + self._requester = None # type: Optional[Union[Requester, str]] # we can't yet create the logcontext, as we don't know the method. self.logcontext = None # type: Optional[LoggingContext] @@ -93,6 +97,28 @@ def __repr__(self): self.site.site_tag, ) + @property + def requester(self) -> Optional[Union[Requester, str]]: + return self._requester + + @requester.setter + def requester(self, value: Union[Requester, str]) -> None: + # Store the requester, and update some properties based on it. + + # This should only be called once. + assert self._requester is None + + self._requester = value + + # A logging context should exist by now (and have a ContextRequest). + assert self.logcontext is not None + assert self.logcontext.request is not None + + ( + self.logcontext.request.requester, + self.logcontext.request.authenticated_entity, + ) = self.get_authenticated_entity() + def get_request_id(self): return "%s-%i" % (self.get_method(), self.request_seq) @@ -140,22 +166,22 @@ def get_authenticated_entity(self) -> Tuple[Optional[str], Optional[str]]: Requester.authenticated_entity. """ # Convert the requester into a string that we can log - if isinstance(self.requester, str): - return self.requester, None - elif isinstance(self.requester, Requester): - requester = self.requester.user.to_string() - authenticated_entity = self.requester.authenticated_entity + if isinstance(self._requester, str): + return self._requester, None + elif isinstance(self._requester, Requester): + requester = self._requester.user.to_string() + authenticated_entity = self._requester.authenticated_entity # If this is a request where the target user doesn't match the user who # authenticated (e.g. and admin is puppetting a user) then we return both. - if self.requester.user.to_string() != authenticated_entity: + if self._requester.user.to_string() != authenticated_entity: return requester, authenticated_entity return requester, None - elif self.requester is not None: + elif self._requester is not None: # This shouldn't happen, but we log it so we don't lose information # and can see that we're doing something wrong. - return repr(self.requester), None # type: ignore[unreachable] + return repr(self._requester), None # type: ignore[unreachable] return None, None @@ -165,7 +191,21 @@ def render(self, resrc): # create a LogContext for this request request_id = self.get_request_id() - self.logcontext = LoggingContext(request_id, request=self) + self.logcontext = LoggingContext( + request_id, + request=ContextRequest( + self.get_request_id(), + self.getClientIP(), + self.site.site_tag, + # The requester is going to be unknown at this point. + None, + None, + self.get_method(), + self.get_redacted_uri(), + self.clientproto.decode("ascii", errors="replace"), + get_request_user_agent(self), + ), + ) # override the Server header which is set by twisted self.setHeader("Server", self.site.server_version_string) @@ -355,9 +395,6 @@ def _finished_processing(self): except Exception as e: logger.warning("Failed to stop metrics: %r", e) - # Break the cycle between SynapseRequest and LoggingContext. - self.logcontext = None - def _should_log_request(self) -> bool: """Whether we should log at INFO that we processed the request.""" if self.path == b"/health": diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 4d207077eed3..b8d0df95953a 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -34,7 +34,6 @@ from twisted.internet import defer, threads if TYPE_CHECKING: - from synapse.http.site import SynapseRequest from synapse.logging.scopecontextmanager import _LogContextScope logger = logging.getLogger(__name__) @@ -181,6 +180,42 @@ def __sub__(self, other: "ContextResourceUsage") -> "ContextResourceUsage": return res +class ContextRequest: + __slots__ = [ + "request_id", + "ip_address", + "site_tag", + "requester", + "authenticated_entity", + "method", + "url", + "protocol", + "user_agent", + ] + + def __init__( + self, + request_id, + ip_address, + site_tag, + requester, + authenticated_entity, + method, + url, + protocol, + user_agent, + ): + self.request_id = request_id + self.ip_address = ip_address + self.site_tag = site_tag + self.requester = requester + self.authenticated_entity = authenticated_entity + self.method = method + self.url = url + self.protocol = protocol + self.user_agent = user_agent + + LoggingContextOrSentinel = Union["LoggingContext", "_Sentinel"] @@ -256,7 +291,7 @@ def __init__( self, name: Optional[str] = None, parent_context: "Optional[LoggingContext]" = None, - request: "Optional[SynapseRequest]" = None, + request: Optional[ContextRequest] = None, ) -> None: self.previous_context = current_context() self.name = name @@ -293,7 +328,7 @@ def __init__( def __str__(self) -> str: if self.request: - return self.request.get_request_id() + return self.request.request_id return "%s@%x" % (self.name, id(self)) @classmethod @@ -569,16 +604,14 @@ def filter(self, record: logging.LogRecord) -> Literal[True]: if request is None: return True - # Avoid a circular import. - from synapse.http import get_request_user_agent - - record.ip_address = request.getClientIP() # type: ignore - record.site_tag = request.site.site_tag # type: ignore - record.requester, record.authenticated_entity = request.get_authenticated_entity() # type: ignore - record.method = request.get_method() # type: ignore - record.url = request.get_redacted_uri() # type: ignore - record.protocol = request.clientproto.decode("ascii", errors="replace") # type: ignore - record.user_agent = get_request_user_agent(request) # type: ignore + record.ip_address = request.ip_address # type: ignore + record.site_tag = request.site_tag # type: ignore + record.requester = request.requester + record.authenticated_entity = request.authenticated_entity # type: ignore + record.method = request.method # type: ignore + record.url = request.url # type: ignore + record.protocol = request.protocol # type: ignore + record.user_agent = request.user_agent # type: ignore return True diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index 296f3e3cdaa9..0bc679e28b2c 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -16,7 +16,9 @@ import logging from io import BytesIO, StringIO -from mock import Mock +from twisted.web.server import Request + +from mock import Mock, patch from synapse.http.site import SynapseRequest from synapse.logging._terse_json import JsonFormatter, TerseJsonFormatter @@ -149,15 +151,22 @@ def test_with_request_context(self): logger = self.get_logger(handler) # A full request isn't needed here. - site = Mock(spec=["site_tag"]) + site = Mock(spec=["site_tag", "server_version_string", "getResourceFor"]) site.site_tag = "test-site" + site.server_version_string = "Server v1" request = SynapseRequest(FakeChannel(site, None)) # Call requestReceived to finish instantiating the object. request.content = BytesIO() - request.process = Mock() - request.requestReceived(b"POST", b"/_matrix/client/versions", b"1.1") + # Partially skip some of the internal processing of SynapseRequest. + request._started_processing = Mock() + request.request_metrics = Mock(spec=["name"]) + with patch.object(Request, "render"): + request.requestReceived(b"POST", b"/_matrix/client/versions", b"1.1") + + # Also set the requester to ensure the processing works. + request.requester = "@foo:test" - with LoggingContext(request=request): + with LoggingContext(parent_context=request.logcontext): logger.info("Hello there, %s!", "wally") log = self.get_log_line() @@ -182,7 +191,7 @@ def test_with_request_context(self): self.assertTrue(log["request"].startswith("POST-")) self.assertEqual(log["ip_address"], "127.0.0.1") self.assertEqual(log["site_tag"], "test-site") - self.assertIsNone(log["requester"]) + self.assertEqual(log["requester"], "@foo:test") self.assertIsNone(log["authenticated_entity"]) self.assertEqual(log["method"], "POST") self.assertEqual(log["url"], "/_matrix/client/versions") From 022fb777c0c1bb8a4a4482ae3d0dfaffe5c6e035 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 24 Mar 2021 08:15:13 -0400 Subject: [PATCH 07/12] Default the authenticated entity to the requester if not given. --- synapse/http/site.py | 7 +++++-- synapse/logging/context.py | 2 +- tests/logging/test_terse_json.py | 6 +++--- 3 files changed, 9 insertions(+), 6 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index d6f43caad170..70b2ded0a555 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -115,9 +115,12 @@ def requester(self, value: Union[Requester, str]) -> None: assert self.logcontext.request is not None ( - self.logcontext.request.requester, - self.logcontext.request.authenticated_entity, + requester, + authenticated_entity, ) = self.get_authenticated_entity() + self.logcontext.request.requester = requester + # If there's no authenticated entity, it was the requester. + self.logcontext.request.authenticated_entity = authenticated_entity or requester def get_request_id(self): return "%s-%i" % (self.get_method(), self.request_seq) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index b8d0df95953a..aff5f87ed575 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -606,7 +606,7 @@ def filter(self, record: logging.LogRecord) -> Literal[True]: record.ip_address = request.ip_address # type: ignore record.site_tag = request.site_tag # type: ignore - record.requester = request.requester + record.requester = request.requester # type: ignore record.authenticated_entity = request.authenticated_entity # type: ignore record.method = request.method # type: ignore record.url = request.url # type: ignore diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index 0bc679e28b2c..bfe0d11c9364 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -16,10 +16,10 @@ import logging from io import BytesIO, StringIO -from twisted.web.server import Request - from mock import Mock, patch +from twisted.web.server import Request + from synapse.http.site import SynapseRequest from synapse.logging._terse_json import JsonFormatter, TerseJsonFormatter from synapse.logging.context import LoggingContext, LoggingContextFilter @@ -192,7 +192,7 @@ def test_with_request_context(self): self.assertEqual(log["ip_address"], "127.0.0.1") self.assertEqual(log["site_tag"], "test-site") self.assertEqual(log["requester"], "@foo:test") - self.assertIsNone(log["authenticated_entity"]) + self.assertEqual(log["authenticated_entity"], "@foo:test") self.assertEqual(log["method"], "POST") self.assertEqual(log["url"], "/_matrix/client/versions") self.assertEqual(log["protocol"], "1.1") From 7f5b5f654bcfbc7ddb88de6a4b148b216f97d725 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 24 Mar 2021 08:41:33 -0400 Subject: [PATCH 08/12] Clarify a comment. --- synapse/logging/context.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index aff5f87ed575..c7e2a95b68a6 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -323,7 +323,7 @@ def __init__( self.scope = self.parent_context.scope if request is not None: - # the request_id param overrides the request_id from the parent context + # the request param overrides the request from the parent context self.request = request def __str__(self) -> str: From eee16ddfe4863f267412f5604de010bcb34eb156 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 24 Mar 2021 08:44:09 -0400 Subject: [PATCH 09/12] Fix more comments. --- synapse/logging/context.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index c7e2a95b68a6..13f97cd78f84 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -684,8 +684,8 @@ def set_current_context(context: LoggingContextOrSentinel) -> LoggingContextOrSe def nested_logging_context(suffix: str) -> LoggingContext: """Creates a new logging context as a child of another. - The nested logging context will have a 'request_id' made up of the parent context's - request_id, plus the given suffix. + The nested logging context will have a 'name' made up of the parent context's + name, plus the given suffix. CPU/db usage stats will be added to the parent context's on exit. @@ -695,7 +695,7 @@ def nested_logging_context(suffix: str) -> LoggingContext: # ... do stuff Args: - suffix: suffix to add to the parent context's 'request_id'. + suffix: suffix to add to the parent context's 'name'. Returns: LoggingContext: new logging context. From 69a7039c146b0d5cd092528a352cc24948a8d01d Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 24 Mar 2021 11:40:22 -0400 Subject: [PATCH 10/12] Use attrs. --- synapse/http/site.py | 18 ++++++++-------- synapse/logging/context.py | 44 ++++++++++---------------------------- 2 files changed, 20 insertions(+), 42 deletions(-) diff --git a/synapse/http/site.py b/synapse/http/site.py index 70b2ded0a555..c0c873ce3205 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -197,16 +197,16 @@ def render(self, resrc): self.logcontext = LoggingContext( request_id, request=ContextRequest( - self.get_request_id(), - self.getClientIP(), - self.site.site_tag, + request_id=request_id, + ip_address=self.getClientIP(), + site_tag=self.site.site_tag, # The requester is going to be unknown at this point. - None, - None, - self.get_method(), - self.get_redacted_uri(), - self.clientproto.decode("ascii", errors="replace"), - get_request_user_agent(self), + requester=None, + authenticated_entity=None, + method=self.get_method(), + url=self.get_redacted_uri(), + protocol=self.clientproto.decode("ascii", errors="replace"), + user_agent=get_request_user_agent(self), ), ) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 13f97cd78f84..ae7a07f13b05 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -29,6 +29,7 @@ import warnings from typing import TYPE_CHECKING, Optional, Tuple, TypeVar, Union +import attr from typing_extensions import Literal from twisted.internet import defer, threads @@ -180,40 +181,17 @@ def __sub__(self, other: "ContextResourceUsage") -> "ContextResourceUsage": return res +@attr.s(slots=True) class ContextRequest: - __slots__ = [ - "request_id", - "ip_address", - "site_tag", - "requester", - "authenticated_entity", - "method", - "url", - "protocol", - "user_agent", - ] - - def __init__( - self, - request_id, - ip_address, - site_tag, - requester, - authenticated_entity, - method, - url, - protocol, - user_agent, - ): - self.request_id = request_id - self.ip_address = ip_address - self.site_tag = site_tag - self.requester = requester - self.authenticated_entity = authenticated_entity - self.method = method - self.url = url - self.protocol = protocol - self.user_agent = user_agent + request_id = attr.ib(type=str) + ip_address = attr.ib(type=str) + site_tag = attr.ib(type=str) + requester = attr.ib(type=Optional[str]) + authenticated_entity = attr.ib(type=Optional[str]) + method = attr.ib(type=str) + url = attr.ib(type=str) + protocol = attr.ib(type=str) + user_agent = attr.ib(type=str) LoggingContextOrSentinel = Union["LoggingContext", "_Sentinel"] From 6a3291e969d5cfc4ed83085751cce6b803b9df59 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 24 Mar 2021 11:42:33 -0400 Subject: [PATCH 11/12] Add a docstring. --- synapse/logging/context.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index ae7a07f13b05..4cf7d9897b4f 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -183,6 +183,15 @@ def __sub__(self, other: "ContextResourceUsage") -> "ContextResourceUsage": @attr.s(slots=True) class ContextRequest: + """ + A bundle of attributes from the SynapseRequest object. + + This exists to: + + * Avoid a cycle between LoggingContext and SynapseRequest. + * Be a single variable that can be passed from parent LoggingContexts to + their children. + """ request_id = attr.ib(type=str) ip_address = attr.ib(type=str) site_tag = attr.ib(type=str) From e10d6a1c46393d0f7935bc4b23e707ec6fee15fe Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 24 Mar 2021 12:30:23 -0400 Subject: [PATCH 12/12] Lint --- synapse/logging/context.py | 1 + 1 file changed, 1 insertion(+) diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 4cf7d9897b4f..efa6d5278b66 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -192,6 +192,7 @@ class ContextRequest: * Be a single variable that can be passed from parent LoggingContexts to their children. """ + request_id = attr.ib(type=str) ip_address = attr.ib(type=str) site_tag = attr.ib(type=str)