From 7c249dd157ceac25955872c332cea1542b0592ef Mon Sep 17 00:00:00 2001 From: Sean Quah Date: Mon, 4 Oct 2021 19:20:22 +0100 Subject: [PATCH 1/3] Fix logging context warnings when losing replication connection Instead of triggering `__exit__` manually on the replication handler's logging context, use it as a context manager so that there is an `__enter__` call to balance the `__exit__`. --- changelog.d/10984.misc | 1 + synapse/replication/tcp/protocol.py | 5 +++-- synapse/replication/tcp/redis.py | 5 +++-- 3 files changed, 7 insertions(+), 4 deletions(-) create mode 100644 changelog.d/10984.misc diff --git a/changelog.d/10984.misc b/changelog.d/10984.misc new file mode 100644 index 000000000000..45cad9fbb510 --- /dev/null +++ b/changelog.d/10984.misc @@ -0,0 +1 @@ +Fix spurious "Expected logging context replication_command_handler-############### was lost" warnings when losing the replication connection. diff --git a/synapse/replication/tcp/protocol.py b/synapse/replication/tcp/protocol.py index 8c80153ab6e0..08ee351b3cf3 100644 --- a/synapse/replication/tcp/protocol.py +++ b/synapse/replication/tcp/protocol.py @@ -434,8 +434,9 @@ def on_connection_closed(self): if self.transport: self.transport.unregisterProducer() - # mark the logging context as finished - self._logging_context.__exit__(None, None, None) + # mark the logging context as finished by triggering `__exit__()` + with self._logging_context: + pass def __str__(self): addr = None diff --git a/synapse/replication/tcp/redis.py b/synapse/replication/tcp/redis.py index 062fe2f33e0c..5267a23457dc 100644 --- a/synapse/replication/tcp/redis.py +++ b/synapse/replication/tcp/redis.py @@ -182,8 +182,9 @@ def connectionLost(self, reason): super().connectionLost(reason) self.synapse_handler.lost_connection(self) - # mark the logging context as finished - self._logging_context.__exit__(None, None, None) + # mark the logging context as finished by triggering `__exit__()` + with self._logging_context: + pass def send_command(self, cmd: Command): """Send a command if connection has been established. From b10e085975ed7ee6c3af825905279feb1ec62204 Mon Sep 17 00:00:00 2001 From: Sean Quah <8349537+squahtx@users.noreply.github.com> Date: Tue, 5 Oct 2021 16:07:59 +0100 Subject: [PATCH 2/3] Reword changelog Co-authored-by: Brendan Abolivier --- changelog.d/10984.misc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelog.d/10984.misc b/changelog.d/10984.misc index 45cad9fbb510..86c4081cc49d 100644 --- a/changelog.d/10984.misc +++ b/changelog.d/10984.misc @@ -1 +1 @@ -Fix spurious "Expected logging context replication_command_handler-############### was lost" warnings when losing the replication connection. +Fix spurious warnings about losing the logging context on the `ReplicationCommandHandler` when losing the replication connection. From 9823350fc1a2233c1ef0987f9a437e99c5590475 Mon Sep 17 00:00:00 2001 From: Sean Quah Date: Wed, 6 Oct 2021 13:55:48 +0100 Subject: [PATCH 3/3] Avoid reactivating random logging context and restoring incorrect logging context --- synapse/replication/tcp/protocol.py | 17 ++++++++++++----- synapse/replication/tcp/redis.py | 17 ++++++++++++----- 2 files changed, 24 insertions(+), 10 deletions(-) diff --git a/synapse/replication/tcp/protocol.py b/synapse/replication/tcp/protocol.py index 08ee351b3cf3..7bae36db169b 100644 --- a/synapse/replication/tcp/protocol.py +++ b/synapse/replication/tcp/protocol.py @@ -182,9 +182,13 @@ 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. - self._logging_context = BackgroundProcessLoggingContext( - "replication-conn", self.conn_id - ) + with PreserveLoggingContext(): + # thanks to `PreserveLoggingContext()`, the new logcontext is guaranteed to + # capture the sentinel context as its containing context and won't prevent + # GC of / unintentionally reactivate what would be the current context. + self._logging_context = BackgroundProcessLoggingContext( + "replication-conn", self.conn_id + ) def connectionMade(self): logger.info("[%s] Connection established", self.id()) @@ -435,8 +439,11 @@ def on_connection_closed(self): self.transport.unregisterProducer() # mark the logging context as finished by triggering `__exit__()` - with self._logging_context: - pass + with PreserveLoggingContext(): + with self._logging_context: + pass + # the sentinel context is now active, which may not be correct. + # PreserveLoggingContext() will restore the correct logging context. def __str__(self): addr = None diff --git a/synapse/replication/tcp/redis.py b/synapse/replication/tcp/redis.py index 5267a23457dc..8d28bd3f3fcc 100644 --- a/synapse/replication/tcp/redis.py +++ b/synapse/replication/tcp/redis.py @@ -100,9 +100,13 @@ def __init__(self, *args, **kwargs): # 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_command_handler" - ) + with PreserveLoggingContext(): + # thanks to `PreserveLoggingContext()`, the new logcontext is guaranteed to + # capture the sentinel context as its containing context and won't prevent + # GC of / unintentionally reactivate what would be the current context. + self._logging_context = BackgroundProcessLoggingContext( + "replication_command_handler" + ) def connectionMade(self): logger.info("Connected to redis") @@ -183,8 +187,11 @@ def connectionLost(self, reason): self.synapse_handler.lost_connection(self) # mark the logging context as finished by triggering `__exit__()` - with self._logging_context: - pass + with PreserveLoggingContext(): + with self._logging_context: + pass + # the sentinel context is now active, which may not be correct. + # PreserveLoggingContext() will restore the correct logging context. def send_command(self, cmd: Command): """Send a command if connection has been established.