From 3d4945a26d2b592dc29c01e52d4dfacc1c44b3fd Mon Sep 17 00:00:00 2001 From: Itamar Turner-Trauring Date: Tue, 12 Dec 2023 10:33:25 -0500 Subject: [PATCH 1/3] Write out Eliot messages in a thread. --- src/allmydata/test/test_eliotutil.py | 53 +++++++++------------------- src/allmydata/util/eliotutil.py | 20 +++++------ 2 files changed, 26 insertions(+), 47 deletions(-) diff --git a/src/allmydata/test/test_eliotutil.py b/src/allmydata/test/test_eliotutil.py index 52d709e4c4..5b191cd92f 100644 --- a/src/allmydata/test/test_eliotutil.py +++ b/src/allmydata/test/test_eliotutil.py @@ -1,20 +1,7 @@ """ Tests for ``allmydata.util.eliotutil``. - -Ported to Python 3. """ -from __future__ import ( - unicode_literals, - print_function, - absolute_import, - division, -) - -from future.utils import PY2 -if PY2: - from future.builtins import filter, map, zip, ascii, chr, hex, input, next, oct, open, pow, round, super, bytes, dict, list, object, range, str, max, min # noqa: F401 - from sys import stdout import logging @@ -67,6 +54,7 @@ _parse_destination_description, _EliotLogging, ) +from ..util.deferredutil import async_to_deferred from .common import ( SyncTestCase, @@ -214,13 +202,14 @@ def test_regular_file(self): ) -# Opt out of the great features of common.SyncTestCase because we're -# interacting with Eliot in a very obscure, particular, fragile way. :/ -class EliotLoggingTests(TestCase): +# We need AsyncTestCase because logging happens in a thread tied to the +# reactor. +class EliotLoggingTests(AsyncTestCase): """ Tests for ``_EliotLogging``. """ - def test_stdlib_event_relayed(self): + @async_to_deferred + async def test_stdlib_event_relayed(self): """ An event logged using the stdlib logging module is delivered to the Eliot destination. @@ -228,23 +217,16 @@ def test_stdlib_event_relayed(self): collected = [] service = _EliotLogging([collected.append]) service.startService() - self.addCleanup(service.stopService) - - # The first destination added to the global log destinations gets any - # buffered messages delivered to it. We don't care about those. - # Throw them on the floor. Sorry. - del collected[:] logging.critical("oh no") - self.assertThat( - collected, - AfterPreprocessing( - len, - Equals(1), - ), + await service.stopService() + + self.assertTrue( + "oh no" in str(collected[-1]), collected ) - def test_twisted_event_relayed(self): + @async_to_deferred + async def test_twisted_event_relayed(self): """ An event logged with a ``twisted.logger.Logger`` is delivered to the Eliot destination. @@ -252,15 +234,13 @@ def test_twisted_event_relayed(self): collected = [] service = _EliotLogging([collected.append]) service.startService() - self.addCleanup(service.stopService) from twisted.logger import Logger Logger().critical("oh no") - self.assertThat( - collected, - AfterPreprocessing( - len, Equals(1), - ), + await service.stopService() + + self.assertTrue( + "oh no" in str(collected[-1]), collected ) def test_validation_failure(self): @@ -318,7 +298,6 @@ def test_skipped(self): ) - class LogCallDeferredTests(TestCase): """ Tests for ``log_call_deferred``. diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index 94d34f96f8..9e3cf6ae08 100644 --- a/src/allmydata/util/eliotutil.py +++ b/src/allmydata/util/eliotutil.py @@ -36,7 +36,7 @@ optional, provides, ) - +from twisted.internet import reactor from eliot import ( ILogger, Message, @@ -58,6 +58,7 @@ DeferredContext, inline_callbacks, ) +from eliot.logwriter import ThreadedWriter from twisted.python.usage import ( UsageError, ) @@ -75,7 +76,7 @@ from twisted.internet.defer import ( maybeDeferred, ) -from twisted.application.service import Service +from twisted.application.service import MultiService from .jsonbytes import AnyBytesJSONEncoder @@ -144,7 +145,7 @@ def opt_help_eliot_destinations(self): raise SystemExit(0) -class _EliotLogging(Service): +class _EliotLogging(MultiService): """ A service which adds stdout as an Eliot destination while it is running. """ @@ -153,23 +154,22 @@ def __init__(self, destinations): :param list destinations: The Eliot destinations which will is added by this service. """ - self.destinations = destinations - + MultiService.__init__(self) + for destination in destinations: + service = ThreadedWriter(destination, reactor) + service.setServiceParent(self) def startService(self): self.stdlib_cleanup = _stdlib_logging_to_eliot_configuration(getLogger()) self.twisted_observer = _TwistedLoggerToEliotObserver() globalLogPublisher.addObserver(self.twisted_observer) - add_destinations(*self.destinations) - return Service.startService(self) + return MultiService.startService(self) def stopService(self): - for dest in self.destinations: - remove_destination(dest) globalLogPublisher.removeObserver(self.twisted_observer) self.stdlib_cleanup() - return Service.stopService(self) + return MultiService.stopService(self) @implementer(ILogObserver) From d5db9e800fedda81c077b1b0eef735e72109d52f Mon Sep 17 00:00:00 2001 From: Itamar Turner-Trauring Date: Tue, 12 Dec 2023 10:37:04 -0500 Subject: [PATCH 2/3] News fragment --- newsfragments/4804.feature | 1 + 1 file changed, 1 insertion(+) create mode 100644 newsfragments/4804.feature diff --git a/newsfragments/4804.feature b/newsfragments/4804.feature new file mode 100644 index 0000000000..23b3d3c6e6 --- /dev/null +++ b/newsfragments/4804.feature @@ -0,0 +1 @@ +Logs are now written in a thread, which should make the application more responsive under load. \ No newline at end of file From 451cdd7dcbcea71ba815d1dfbfc2702c42308627 Mon Sep 17 00:00:00 2001 From: Itamar Turner-Trauring Date: Tue, 12 Dec 2023 10:39:18 -0500 Subject: [PATCH 3/3] Fix lint --- src/allmydata/util/eliotutil.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index 9e3cf6ae08..f0d5bffd23 100644 --- a/src/allmydata/util/eliotutil.py +++ b/src/allmydata/util/eliotutil.py @@ -41,8 +41,6 @@ ILogger, Message, FileDestination, - add_destinations, - remove_destination, write_traceback, start_action, )