From b076bc276e881b262048307b6a226061d96c4a8d Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Tue, 20 Apr 2021 09:19:00 -0400 Subject: [PATCH 1/4] Always use the name as the log ID. (#9829) As far as I can tell our logging contexts are meant to log the request ID, or sometimes the request ID followed by a suffix (this is generally stored in the name field of LoggingContext). There's also code to log the name@memory location, but I'm not sure this is ever used. This simplifies the code paths to require every logging context to have a name and use that in logging. For sub-contexts (created via nested_logging_contexts, defer_to_threadpool, Measure) we use the current context's str (which becomes their name or the string "sentinel") and then potentially modify that (e.g. add a suffix). --- changelog.d/9829.bugfix | 1 + synapse/logging/context.py | 14 ++++---------- synapse/metrics/background_process_metrics.py | 15 ++++----------- synapse/replication/tcp/protocol.py | 2 +- synapse/util/metrics.py | 14 +++++++++----- tests/logging/test_terse_json.py | 6 ++++-- tests/test_federation.py | 2 +- tests/util/caches/test_descriptors.py | 6 ++---- 8 files changed, 26 insertions(+), 34 deletions(-) create mode 100644 changelog.d/9829.bugfix diff --git a/changelog.d/9829.bugfix b/changelog.d/9829.bugfix new file mode 100644 index 0000000000..d0c1e49fd8 --- /dev/null +++ b/changelog.d/9829.bugfix @@ -0,0 +1 @@ +Fix the log lines of nested logging contexts. diff --git a/synapse/logging/context.py b/synapse/logging/context.py index e78343f554..dbd7d3a33a 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -277,7 +277,7 @@ class LoggingContext: def __init__( self, - name: Optional[str] = None, + name: str, parent_context: "Optional[LoggingContext]" = None, request: Optional[ContextRequest] = None, ) -> None: @@ -315,9 +315,7 @@ class LoggingContext: self.request = request def __str__(self) -> str: - if self.request: - return self.request.request_id - return "%s@%x" % (self.name, id(self)) + return self.name @classmethod def current_context(cls) -> LoggingContextOrSentinel: @@ -694,17 +692,13 @@ def nested_logging_context(suffix: str) -> LoggingContext: "Starting nested logging context from sentinel context: metrics will be lost" ) parent_context = None - prefix = "" - request = None else: assert isinstance(curr_context, LoggingContext) parent_context = curr_context - prefix = str(parent_context.name) - request = parent_context.request + prefix = str(curr_context) return LoggingContext( prefix + "-" + suffix, parent_context=parent_context, - request=request, ) @@ -895,7 +889,7 @@ def defer_to_threadpool(reactor, threadpool, f, *args, **kwargs): parent_context = curr_context def g(): - with LoggingContext(parent_context=parent_context): + with LoggingContext(str(curr_context), parent_context=parent_context): return f(*args, **kwargs) return make_deferred_yieldable(threads.deferToThreadPool(reactor, threadpool, g)) diff --git a/synapse/metrics/background_process_metrics.py b/synapse/metrics/background_process_metrics.py index e8a9096c03..78e9cfbc26 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, Union +from typing import TYPE_CHECKING, Dict, Optional, Set from prometheus_client.core import REGISTRY, Counter, Gauge @@ -199,7 +199,7 @@ def run_as_background_process(desc: str, func, *args, bg_start_span=True, **kwar _background_process_start_count.labels(desc).inc() _background_process_in_flight_count.labels(desc).inc() - with BackgroundProcessLoggingContext(desc, count) as context: + with BackgroundProcessLoggingContext("%s-%s" % (desc, count)) as context: try: ctx = noop_context_manager() if bg_start_span: @@ -242,19 +242,12 @@ class BackgroundProcessLoggingContext(LoggingContext): processes. """ - __slots__ = ["_id", "_proc"] + __slots__ = ["_proc"] - def __init__(self, name: str, id: Optional[Union[int, str]] = None): + def __init__(self, name: str): 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 d10d574246..ba753318bd 100644 --- a/synapse/replication/tcp/protocol.py +++ b/synapse/replication/tcp/protocol.py @@ -185,7 +185,7 @@ class BaseReplicationStreamProtocol(LineOnlyReceiver): # 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. self._logging_context = BackgroundProcessLoggingContext( - "replication-conn", self.conn_id + "replication-conn-%s" % (self.conn_id,) ) def connectionMade(self): diff --git a/synapse/util/metrics.py b/synapse/util/metrics.py index 1023c856d1..019cfa17cc 100644 --- a/synapse/util/metrics.py +++ b/synapse/util/metrics.py @@ -105,7 +105,13 @@ class Measure: "start", ] - def __init__(self, clock, name): + def __init__(self, clock, name: str): + """ + Args: + clock: A n object with a "time()" method, which returns the current + time in seconds. + name: The name of the metric to report. + """ self.clock = clock self.name = name curr_context = current_context() @@ -118,10 +124,8 @@ class Measure: else: assert isinstance(curr_context, LoggingContext) parent_context = curr_context - self._logging_context = LoggingContext( - "Measure[%s]" % (self.name,), parent_context - ) - self.start = None + self._logging_context = LoggingContext(str(curr_context), parent_context) + self.start = None # type: Optional[int] def __enter__(self) -> "Measure": if self.start is not None: diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index 215fd8b0f9..ecf873e2ab 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -138,7 +138,7 @@ class TerseJsonTestCase(LoggerCleanupMixin, TestCase): ] self.assertCountEqual(log.keys(), expected_log_keys) self.assertEqual(log["log"], "Hello there, wally!") - self.assertTrue(log["request"].startswith("name@")) + self.assertEqual(log["request"], "name") def test_with_request_context(self): """ @@ -165,7 +165,9 @@ class TerseJsonTestCase(LoggerCleanupMixin, TestCase): # Also set the requester to ensure the processing works. request.requester = "@foo:test" - with LoggingContext(parent_context=request.logcontext): + with LoggingContext( + request.get_request_id(), parent_context=request.logcontext + ): logger.info("Hello there, %s!", "wally") log = self.get_log_line() diff --git a/tests/test_federation.py b/tests/test_federation.py index 8928597d17..382cedbd5d 100644 --- a/tests/test_federation.py +++ b/tests/test_federation.py @@ -134,7 +134,7 @@ class MessageAcceptTests(unittest.HomeserverTestCase): } ) - with LoggingContext(): + with LoggingContext("test-context"): failure = self.get_failure( self.handler.on_receive_pdu( "test.serv", lying_event, sent_to_us_directly=True diff --git a/tests/util/caches/test_descriptors.py b/tests/util/caches/test_descriptors.py index 2d1f9360e0..8c082e7432 100644 --- a/tests/util/caches/test_descriptors.py +++ b/tests/util/caches/test_descriptors.py @@ -231,8 +231,7 @@ class DescriptorTestCase(unittest.TestCase): @defer.inlineCallbacks def do_lookup(): - with LoggingContext() as c1: - c1.name = "c1" + with LoggingContext("c1") as c1: r = yield obj.fn(1) self.assertEqual(current_context(), c1) return r @@ -274,8 +273,7 @@ class DescriptorTestCase(unittest.TestCase): @defer.inlineCallbacks def do_lookup(): - with LoggingContext() as c1: - c1.name = "c1" + with LoggingContext("c1") as c1: try: d = obj.fn(1) self.assertEqual( From 0a88ec0a879d9fcb6f2202b7cff3766ed5f7253b Mon Sep 17 00:00:00 2001 From: Andrew Morgan <1342360+anoadragon453@users.noreply.github.com> Date: Tue, 20 Apr 2021 14:19:35 +0100 Subject: [PATCH 2/4] Add Application Service registration type requirement + py35, pg95 deprecation notices to v1.32.0 upgrade notes (#9849) Fixes https://github.com/matrix-org/synapse/issues/9846. Adds important removal information from the top of https://github.com/matrix-org/synapse/releases/tag/v1.32.0rc1 into UPGRADE.rst. --- UPGRADE.rst | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/UPGRADE.rst b/UPGRADE.rst index 665821d4ef..7a9b869055 100644 --- a/UPGRADE.rst +++ b/UPGRADE.rst @@ -88,6 +88,14 @@ for example: Upgrading to v1.32.0 ==================== +Dropping support for old Python, Postgres and SQLite versions +------------------------------------------------------------- + +In line with our `deprecation policy `_, +we've dropped support for Python 3.5 and PostgreSQL 9.5, as they are no longer supported upstream. + +This release of Synapse requires Python 3.6+ and PostgresSQL 9.6+ or SQLite 3.22+. + Removal of old List Accounts Admin API -------------------------------------- @@ -98,6 +106,16 @@ has been available since Synapse 1.7.0 (2019-12-13), and is accessible under ``G The deprecation of the old endpoint was announced with Synapse 1.28.0 (released on 2021-02-25). +Application Services must use type ``m.login.application_service`` when registering users +----------------------------------------------------------------------------------------- + +In compliance with the +`Application Service spec `_, +Application Services are now required to use the ``m.login.application_service`` type when registering users via the +``/_matrix/client/r0/register`` endpoint. This behaviour was deprecated in Synapse v1.30.0. + +Please ensure your Application Services are up to date. + Upgrading to v1.29.0 ==================== From e031c7e0cca2422aa2c5d3704adc66723d8094e7 Mon Sep 17 00:00:00 2001 From: Andrew Morgan Date: Tue, 20 Apr 2021 14:31:27 +0100 Subject: [PATCH 3/4] 1.32.0 --- CHANGES.md | 13 +++++++++++-- changelog.d/9829.bugfix | 1 - debian/changelog | 8 ++++++-- synapse/__init__.py | 2 +- 4 files changed, 18 insertions(+), 6 deletions(-) delete mode 100644 changelog.d/9829.bugfix diff --git a/CHANGES.md b/CHANGES.md index 41908f84be..4d48a321c6 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -1,5 +1,5 @@ -Synapse 1.32.0rc1 (2021-04-13) -============================== +Synapse 1.32.0 (2021-04-20) +=========================== **Note:** This release requires Python 3.6+ and Postgres 9.6+ or SQLite 3.22+. @@ -7,6 +7,15 @@ This release removes the deprecated `GET /_synapse/admin/v1/users/` adm This release requires Application Services to use type `m.login.application_services` when registering users via the `/_matrix/client/r0/register` endpoint to comply with the spec. Please ensure your Application Services are up to date. +Bugfixes +-------- + +- Fix the log lines of nested logging contexts. Broke in 1.32.0rc1. ([\#9829](https://github.com/matrix-org/synapse/issues/9829)) + + +Synapse 1.32.0rc1 (2021-04-13) +============================== + Features -------- diff --git a/changelog.d/9829.bugfix b/changelog.d/9829.bugfix deleted file mode 100644 index d0c1e49fd8..0000000000 --- a/changelog.d/9829.bugfix +++ /dev/null @@ -1 +0,0 @@ -Fix the log lines of nested logging contexts. diff --git a/debian/changelog b/debian/changelog index 5d526316fc..83be4497ec 100644 --- a/debian/changelog +++ b/debian/changelog @@ -1,8 +1,12 @@ -matrix-synapse-py3 (1.31.0+nmu1) UNRELEASED; urgency=medium +matrix-synapse-py3 (1.32.0) stable; urgency=medium + [ Dan Callahan ] * Skip tests when DEB_BUILD_OPTIONS contains "nocheck". - -- Dan Callahan Mon, 12 Apr 2021 13:07:36 +0000 + [ Synapse Packaging team ] + * New synapse release 1.32.0. + + -- Synapse Packaging team Tue, 20 Apr 2021 14:28:39 +0100 matrix-synapse-py3 (1.31.0) stable; urgency=medium diff --git a/synapse/__init__.py b/synapse/__init__.py index 125a73d378..79232c4de1 100644 --- a/synapse/__init__.py +++ b/synapse/__init__.py @@ -48,7 +48,7 @@ try: except ImportError: pass -__version__ = "1.32.0rc1" +__version__ = "1.32.0" if bool(os.environ.get("SYNAPSE_TEST_PATCH_LOG_CONTEXTS", False)): # We import here so that we don't have to install a bunch of deps when From 438a8594cb5a74478da36fe33ba98d86e2ca00fc Mon Sep 17 00:00:00 2001 From: Andrew Morgan Date: Tue, 20 Apr 2021 14:47:17 +0100 Subject: [PATCH 4/4] Update v1.32.0 changelog. It's m.login.application_service, not plural --- CHANGES.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGES.md b/CHANGES.md index 4d48a321c6..482863c0e8 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -5,7 +5,7 @@ Synapse 1.32.0 (2021-04-20) This release removes the deprecated `GET /_synapse/admin/v1/users/` admin API. Please use the [v2 API](https://github.com/matrix-org/synapse/blob/develop/docs/admin_api/user_admin_api.rst#query-user-account) instead, which has improved capabilities. -This release requires Application Services to use type `m.login.application_services` when registering users via the `/_matrix/client/r0/register` endpoint to comply with the spec. Please ensure your Application Services are up to date. +This release requires Application Services to use type `m.login.application_service` when registering users via the `/_matrix/client/r0/register` endpoint to comply with the spec. Please ensure your Application Services are up to date. Bugfixes --------