Merge pull request #563 from tahoe-lafs/2987.log_call_deferred

Add Eliot logging helper

Fixes: ticket:2987

src/allmydata/frontends/magic_folder.py

@@ -1764,10 +1764,10 @@ class Downloader(QueueMixin, WriteFileMixin):
         d.addCallback(scan_listing)
         return d.addActionFinish()
 
+    @eliotutil.log_call_deferred(SCAN_REMOTE_COLLECTIVE.action_type)
     def _scan_remote_collective(self, scan_self=False):
         scan_batch = {}  # path -> [(filenode, metadata)]
-        with SCAN_REMOTE_COLLECTIVE().context():
+        d = DeferredContext(self._collective_dirnode.list())
-            d = DeferredContext(self._collective_dirnode.list())
         def scan_collective(dirmap):
             d2 = DeferredContext(defer.succeed(None))
             for dir_name in dirmap:
@@ -1806,26 +1806,26 @@ class Downloader(QueueMixin, WriteFileMixin):
                     self._call_hook(None, 'processed', async=True)  # await this maybe-Deferred??
 
         d.addCallback(_filter_batch_to_deque)
-        return d.addActionFinish()
+        return d.result
 
     def _scan_delay(self):
         return self._poll_interval
 
+    @eliotutil.log_call_deferred(PERFORM_SCAN.action_type)
     @eliotutil.inline_callbacks
     def _perform_scan(self):
-        with PERFORM_SCAN():
+        try:
-            try:
+            yield self._scan_remote_collective()
-                yield self._scan_remote_collective()
+            self._status_reporter(
-                self._status_reporter(
+                True, 'Magic folder is working',
-                    True, 'Magic folder is working',
+                'Last scan: %s' % self.nice_current_time(),
-                    'Last scan: %s' % self.nice_current_time(),
+            )
-                )
+        except Exception as e:
-            except Exception as e:
+            write_traceback()
-                write_traceback()
+            self._status_reporter(
-                self._status_reporter(
+                False, 'Remote scan has failed: %s' % str(e),
-                    False, 'Remote scan has failed: %s' % str(e),
+                'Last attempted at %s' % self.nice_current_time(),
-                    'Last attempted at %s' % self.nice_current_time(),
+            )
-                )
 
     def _process(self, item):
         """

src/allmydata/test/test_eliotutil.py

@@ -21,6 +21,7 @@ from testtools import (
 )
 from testtools.matchers import (
     Is,
+    IsInstance,
     MatchesStructure,
     Equals,
     AfterPreprocessing,
@@ -28,6 +29,7 @@ from testtools.matchers import (
 from testtools.twistedsupport import (
     has_no_result,
     succeeded,
+    failed,
 )
 
 from eliot import (
@@ -55,6 +57,7 @@ from .eliotutil import (
 from ..util.eliotutil import (
     eliot_friendly_generator_function,
     inline_callbacks,
+    log_call_deferred,
     _parse_destination_description,
     _EliotLogging,
 )
@@ -527,3 +530,44 @@ class EliotLoggingTests(TestCase):
                 len, Equals(1),
             ),
         )
+
+class LogCallDeferredTests(TestCase):
+    """
+    Tests for ``log_call_deferred``.
+    """
+    @capture_logging(
+        lambda self, logger:
+        assertHasAction(self, logger, u"the-action", succeeded=True),
+    )
+    def test_return_value(self, logger):
+        """
+        The decorated function's return value is passed through.
+        """
+        result = object()
+        @log_call_deferred(action_type=u"the-action")
+        def f():
+            return result
+        self.assertThat(f(), succeeded(Is(result)))
+
+    @capture_logging(
+        lambda self, logger:
+        assertHasAction(self, logger, u"the-action", succeeded=False),
+    )
+    def test_raise_exception(self, logger):
+        """
+        An exception raised by the decorated function is passed through.
+        """
+        class Result(Exception):
+            pass
+        @log_call_deferred(action_type=u"the-action")
+        def f():
+            raise Result()
+        self.assertThat(
+            f(),
+            failed(
+                AfterPreprocessing(
+                    lambda f: f.value,
+                    IsInstance(Result),
+                ),
+            ),
+        )

src/allmydata/test/test_magic_folder.py

@@ -41,6 +41,7 @@ from .eliotutil import (
 )
 from ..util.eliotutil import (
     inline_callbacks,
+    log_call_deferred,
 )
 
 _debug = False
@@ -523,6 +524,7 @@ class FileOperationsHelper(object):
         self._inotify = fake_inotify  # fixme?
         self._fake_inotify = inject_events
 
+    @log_call_deferred(action_type=u"fileops:move")
     def move(self, from_path_u, to_path_u):
         from_fname = from_path_u
         to_fname = to_path_u
@@ -534,6 +536,7 @@ class FileOperationsHelper(object):
         # self._uploader._notifier.event(to_filepath(from_fname), self._inotify.IN_MOVED_FROM)
         return d
 
+    @log_call_deferred(action_type=u"fileops:write")
     def write(self, path_u, contents):
         fname = path_u
         if not os.path.exists(fname):
@@ -546,6 +549,7 @@ class FileOperationsHelper(object):
         self._maybe_notify(fname, self._inotify.IN_CLOSE_WRITE)
         return d
 
+    @log_call_deferred(action_type=u"fileops:mkdir")
     def mkdir(self, path_u):
         fname = path_u
         d = self._uploader.set_hook('inotify')
@@ -553,6 +557,7 @@ class FileOperationsHelper(object):
         self._maybe_notify(fname, self._inotify.IN_CREATE | self._inotify.IN_ISDIR)
         return d
 
+    @log_call_deferred(action_type=u"fileops:delete")
     def delete(self, path_u):
         fname = path_u
         d = self._uploader.set_hook('inotify')

src/allmydata/util/eliotutil.py

@@ -53,17 +53,17 @@ from attr.validators import (
 from eliot import (
     ILogger,
     Message,
+    Field,
     FileDestination,
     add_destinations,
     remove_destination,
     write_traceback,
-)
+    start_action,
-from eliot import (
-    Field,
 )
 from eliot._validation import (
     ValidationError,
 )
+from eliot.twisted import DeferredContext
 
 from twisted.python.usage import (
     UsageError,
@@ -81,6 +81,7 @@ from twisted.logger import (
 )
 from twisted.internet.defer import (
     inlineCallbacks,
+    maybeDeferred,
 )
 from twisted.application.service import Service
 
@@ -470,3 +471,20 @@ class _DestinationParser(object):
 
 
 _parse_destination_description = _DestinationParser().parse
+
+def log_call_deferred(action_type):
+    """
+    Like ``eliot.log_call`` but for functions which return ``Deferred``.
+    """
+    def decorate_log_call_deferred(f):
+        @wraps(f)
+        def logged_f(*a, **kw):
+            # Use the action's context method to avoid ending the action when
+            # the `with` block ends.
+            with start_action(action_type=action_type).context():
+                # Use addActionFinish so that the action finishes when the
+                # Deferred fires.
+                d = maybeDeferred(f, *a, **kw)
+                return DeferredContext(d).addActionFinish()
+        return logged_f
+    return decorate_log_call_deferred