Changeset e424270 in trunk

Timestamp:

2019-03-08T12:46:36Z (6 years ago)

Author:

GitHub <noreply@…>

Branches:

master

Children:

c45b91e

Parents:

c8a3dbf (diff), 39694fc (diff)
Note: this is a merge changeset, the changes displayed below correspond to the merge itself.
Use the (diff) links above to see all the changes relative to each parent.

git-author:

Jean-Paul Calderone <exarkun@…> (2019-03-08 12:46:36)

git-committer:

GitHub <noreply@…> (2019-03-08 12:46:36)

Message:

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

Add Eliot logging helper

Fixes: ticket:2987

Files:

• newsfragments/2987.minor (added)
• src/allmydata/frontends/magic_folder.py (modified) (2 diffs)
• src/allmydata/test/test_eliotutil.py (modified) (4 diffs)
• src/allmydata/test/test_magic_folder.py (modified) (5 diffs)
• src/allmydata/util/eliotutil.py (modified) (3 diffs)

src/allmydata/frontends/magic_folder.py ¶

@@ -1765 +1765 @@
         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))
@@ -1807 +1807 @@
 
         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:
-                yield self._scan_remote_collective()
-                self._status_reporter(
-                    True, 'Magic folder is working',
-                    'Last scan: %s' % self.nice_current_time(),
-                )
-            except Exception as e:
-                write_traceback()
-                self._status_reporter(
-                    False, 'Remote scan has failed: %s' % str(e),
-                    'Last attempted at %s' % self.nice_current_time(),
-                )
+        try:
+            yield self._scan_remote_collective()
+            self._status_reporter(
+                True, 'Magic folder is working',
+                'Last scan: %s' % self.nice_current_time(),
+            )
+        except Exception as e:
+            write_traceback()
+            self._status_reporter(
+                False, 'Remote scan has failed: %s' % str(e),
+                'Last attempted at %s' % self.nice_current_time(),
+            )
 
     def _process(self, item):

src/allmydata/test/test_eliotutil.py ¶

@@ -22 +22 @@
 from testtools.matchers import (
     Is,
+    IsInstance,
     MatchesStructure,
     Equals,
@@ -29 +30 @@
     has_no_result,
     succeeded,
+    failed,
 )
 
@@ -56 +58 @@
     eliot_friendly_generator_function,
     inline_callbacks,
+    log_call_deferred,
     _parse_destination_description,
     _EliotLogging,
@@ -528 +531 @@
             ),
         )
+
+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 ¶

@@ -42 +42 @@
 from ..util.eliotutil import (
     inline_callbacks,
+    log_call_deferred,
 )
 
@@ -524 +525 @@
         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
@@ -535 +537 @@
         return d
 
+    @log_call_deferred(action_type=u"fileops:write")
     def write(self, path_u, contents):
         fname = path_u
@@ -547 +550 @@
         return d
 
+    @log_call_deferred(action_type=u"fileops:mkdir")
     def mkdir(self, path_u):
         fname = path_u
@@ -554 +558 @@
         return d
 
+    @log_call_deferred(action_type=u"fileops:delete")
     def delete(self, path_u):
         fname = path_u

src/allmydata/util/eliotutil.py ¶

@@ -54 +54 @@
     ILogger,
     Message,
+    Field,
     FileDestination,
     add_destinations,
     remove_destination,
     write_traceback,
-)
-from eliot import (
-    Field,
+    start_action,
 )
 from eliot._validation import (
     ValidationError,
 )
+from eliot.twisted import DeferredContext
 
 from twisted.python.usage import (
@@ -82 +82 @@
 from twisted.internet.defer import (
     inlineCallbacks,
+    maybeDeferred,
 )
 from twisted.application.service import Service
@@ -471 +472 @@
 
 _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