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.