From 217e4c0f48e01db000127ed9bfb5251eefc51a2c Mon Sep 17 00:00:00 2001 From: Junker der Provinz Date: Mon, 9 Nov 2026 19:43:57 +0100 Subject: [PATCH] Fix RemoteHandler no longer sending logs after connecting (#20389) Fixes #17480 Once `RemoteHandler` is connected, `whenConnected` returns a Deferred that has already fired, so `writer` runs synchronously inside `addCallbacks` and clears `_connection_waiter`. The next line then set the waiter to that fired Deferred, so every later `_connect` call returned early and logs stopped after the first line or two. This sets the waiter before adding the callbacks, so a callback that runs right away can still clear it. The new test logs a few more lines over an existing connection and checks that they all arrive. The bug came in with #9591, hence v1.30.0 in the changelog. Thanks to @haarp for tracking this down and for the detailed reproduction steps. ### Pull Request Checklist * [x] Pull request is based on the develop branch * [x] Pull request includes a [changelog file](https://element-hq.github.io/synapse/latest/development/contributing_guide.html#changelog). The entry should: - Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from `EventStore` to `EventWorkerStore`.". - Use markdown where necessary, mostly for `code blocks`. - End with either a period (.) or an exclamation mark (!). - Start with a capital letter. - Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry. * [x] [Code style](https://element-hq.github.io/synapse/latest/code_style.html) is correct (run the [linters](https://element-hq.github.io/synapse/latest/development/contributing_guide.html#run-the-linters)) --- changelog.d/20389.bugfix | 1 + synapse/logging/_remote.py | 4 +++- tests/logging/test_remote_handler.py | 25 +++++++++++++++++++++++++ 3 files changed, 29 insertions(+), 1 deletion(-) create mode 100644 changelog.d/20389.bugfix diff --git a/changelog.d/20389.bugfix b/changelog.d/20389.bugfix new file mode 100644 index 0000000000..78ad1f0f16 --- /dev/null +++ b/changelog.d/20389.bugfix @@ -0,0 +1 @@ +Fix a bug introduced in Synapse v1.30.0 where `synapse.logging.RemoteHandler` stopped sending logs shortly after connecting. Thanks to @haarp for the diagnosis. diff --git a/synapse/logging/_remote.py b/synapse/logging/_remote.py index b10c3b9b01..a5241a8ae9 100644 --- a/synapse/logging/_remote.py +++ b/synapse/logging/_remote.py @@ -198,9 +198,11 @@ class RemoteHandler(logging.Handler): self._producer.resumeProducing() self._connection_waiter = None + # Set the waiter before adding callbacks: if we are already connected + # they run synchronously and clear it again. deferred: Deferred = self._service.whenConnected(failAfterFailures=1) - deferred.addCallbacks(writer, fail) self._connection_waiter = deferred + deferred.addCallbacks(writer, fail) def _handle_pressure(self) -> None: """ diff --git a/tests/logging/test_remote_handler.py b/tests/logging/test_remote_handler.py index 68bdc28573..1a38268413 100644 --- a/tests/logging/test_remote_handler.py +++ b/tests/logging/test_remote_handler.py @@ -75,6 +75,31 @@ class RemoteHandlerTestCase(LoggerCleanupMixin, TestCase): # Ensure the data passed through properly. self.assertEqual(logs[0], "Hello there, wally!") + def test_log_output_after_connecting(self) -> None: + """ + The remote handler keeps delivering logs once it is connected. + """ + handler = RemoteHandler("127.0.0.1", 9000, _reactor=self.reactor) + logger = self.get_logger(handler) + + logger.info("Hello there, %s!", "wally") + + # Trigger the connection + client, server = connect_logging_client(self.reactor, 0) + client_transport = checked_cast(FakeTransport, client.transport) + client_transport.flush() + + # Log over the existing connection + for i in range(3): + logger.info("more %s", i) + client_transport.flush() + + logs = server.data.decode("utf8").splitlines() + self.assertEqual( + ["Hello there, wally!", "more 0", "more 1", "more 2"], + logs, + ) + def test_log_backpressure_debug(self) -> None: """ When backpressure is hit, DEBUG logs will be shed.