Merge pull request #570 from tahoe-lafs/2997.windows-magic-folder-watch-subtree

Make Magic-Folders more responsive on Windows (and fix the test suite).

Fixes: ticket:2997

.appveyor.yml

@@ -71,6 +71,14 @@ artifacts:
   - path: 'dist\*'
   - path: trial_test_log.txt
     name: Trial test.log
+  - path: eliot.log
+    name: Eliot test log
+
+on_failure:
+  # Artifacts are not normally uploaded when the job fails.  To get the test
+  # logs, we have to push them ourselves.
+  - ps: Push-AppveyorArtifact _trial_temp\test.log -Filename trial.log
+  - ps: Push-AppveyorArtifact eliot.log -Filename eliot.log
 
 #on_success:
 #  You can use this step to upload your artifacts to a public website.

newsfragments/2997.bugfix

@@ -0,0 +1 @@
+The Magic-Folder frontend is now more responsive to subtree changes on Windows.

src/allmydata/frontends/magic_folder.py

@@ -1153,7 +1153,7 @@ class Uploader(QueueMixin):
                     | IN_EXCL_UNLINK
                     )
         self._notifier.watch(self._local_filepath, mask=self.mask, callbacks=[self._notify],
-                             recursive=False)#True)
+                             recursive=True)
 
     def start_monitoring(self):
         action = START_MONITORING(**self._log_fields)
@@ -1281,7 +1281,12 @@ class Uploader(QueueMixin):
                 success_fields[u"ignored"] = True
             else:
                 self._add_pending(relpath_u)
-                self._call_hook(path, 'inotify')
+
+            # Always fire the inotify hook.  If an accident of timing causes a
+            # second inotify event for a particular path before the first has
+            # been processed, the expectation is still that any code that was
+            # waiting for the second inotify event should be notified.
+            self._call_hook(path, 'inotify')
             action.add_success_fields(**success_fields)
 
     def _process(self, item):

src/allmydata/test/test_magic_folder.py

@@ -5,6 +5,7 @@ import mock
 from os.path import join, exists, isdir
 
 from twisted.internet import defer, task, reactor
+from twisted.python.filepath import FilePath
 
 from testtools import (
     skipIf,
@@ -17,6 +18,7 @@ from testtools.matchers import (
 )
 
 from eliot import (
+    Message,
     start_action,
 )
 from eliot.twisted import DeferredContext
@@ -514,6 +516,15 @@ def iterate(magic):
     yield iterate_downloader(magic)
 
 
+@inline_callbacks
+def notify_when_pending(uploader, filename):
+    with start_action(action_type=u"notify-when-pending", filename=filename):
+        relpath = uploader._get_relpath(FilePath(filename))
+        while not uploader.is_pending(relpath):
+            Message.log(message_type=u"not-pending")
+            yield uploader.set_hook('inotify')
+
+
 class FileOperationsHelper(object):
     """
     This abstracts all file operations we might do in magic-folder unit-tests.
@@ -525,6 +536,7 @@ class FileOperationsHelper(object):
 
     We could write this as a mixin instead; might fit existing style better?
     """
+    _timeout = 5.0
 
     def __init__(self, uploader, inject_events=False):
         self._uploader = uploader
@@ -541,7 +553,7 @@ class FileOperationsHelper(object):
         self._maybe_notify(to_fname, self._inotify.IN_MOVED_TO)
         # hmm? we weren't faking IN_MOVED_FROM previously .. but seems like we should have been?
         # self._uploader._notifier.event(to_filepath(from_fname), self._inotify.IN_MOVED_FROM)
-        return d
+        return d.addTimeout(self._timeout, reactor)
 
     @log_call_deferred(action_type=u"fileops:write")
     def write(self, path_u, contents):
@@ -549,12 +561,13 @@ class FileOperationsHelper(object):
         if not os.path.exists(fname):
             self._maybe_notify(fname, self._inotify.IN_CREATE)
 
-        d = self._uploader.set_hook('inotify')
+        d = notify_when_pending(self._uploader, path_u)
+
         with open(fname, "wb") as f:
             f.write(contents)
 
         self._maybe_notify(fname, self._inotify.IN_CLOSE_WRITE)
-        return d
+        return d.addTimeout(self._timeout, reactor)
 
     @log_call_deferred(action_type=u"fileops:mkdir")
     def mkdir(self, path_u):
@@ -562,7 +575,7 @@ class FileOperationsHelper(object):
         d = self._uploader.set_hook('inotify')
         os.mkdir(fname)
         self._maybe_notify(fname, self._inotify.IN_CREATE | self._inotify.IN_ISDIR)
-        return d
+        return d.addTimeout(self._timeout, reactor)
 
     @log_call_deferred(action_type=u"fileops:delete")
     def delete(self, path_u):
@@ -571,7 +584,7 @@ class FileOperationsHelper(object):
         os.unlink(fname)
 
         self._maybe_notify(fname, self._inotify.IN_DELETE)
-        return d
+        return d.addTimeout(self._timeout, reactor)
 
     def _maybe_notify(self, fname, mask):
         if self._fake_inotify:
@@ -1890,16 +1903,19 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
     @inline_callbacks
     def test_create_file_in_sub_directory(self):
         reldir_u = u'subdir'
-        relpath_u = os.path.join(reldir_u, u'some-file')
+        # The OS and the DMD may have conflicting conventions for directory
+        # the separator.  Construct a value for each.
+        dmd_relpath_u = u'/'.join((reldir_u, u'some-file'))
+        platform_relpath_u = join(reldir_u, u'some-file')
         content = u'some great content'
         yield self._create_directory_with_file(
-            relpath_u,
+            platform_relpath_u,
             content,
         )
         # The new directory and file should have been noticed and uploaded.
         downloader = self.magicfolder.downloader
         encoded_dir_u = magicpath.path2magic(reldir_u + u"/")
-        encoded_path_u = magicpath.path2magic(relpath_u)
+        encoded_path_u = magicpath.path2magic(dmd_relpath_u)
 
         with start_action(action_type=u"retrieve-metadata"):
             dir_node, dir_meta = yield downloader._get_collective_latest_file(
@@ -1916,18 +1932,19 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
 
     @inline_callbacks
     def test_delete_file_in_sub_directory(self):
-        relpath_u = u'subdir/some-file'
+        dmd_relpath_u = u'/'.join((u'subdir', u'some-file'))
+        platform_relpath_u = join(u'subdir', u'some-file')
         content = u'some great content'
         yield self._create_directory_with_file(
-            relpath_u,
+            platform_relpath_u,
             content,
         )
         # Delete the file in the sub-directory.
-        yield self.fileops.delete(os.path.join(self.local_dir, relpath_u))
+        yield self.fileops.delete(os.path.join(self.local_dir, platform_relpath_u))
         # Let the deletion be processed.
         yield iterate(self.magicfolder)
         # Verify the deletion was uploaded.
-        encoded_path_u = magicpath.path2magic(relpath_u)
+        encoded_path_u = magicpath.path2magic(dmd_relpath_u)
         downloader = self.magicfolder.downloader
         node, metadata = yield downloader._get_collective_latest_file(encoded_path_u)
         self.assertThat(node, Not(Is(None)))

src/allmydata/util/eliotutil.py

@@ -18,6 +18,9 @@ __all__ = [
     "opt_help_eliot_destinations",
     "validateInstanceOf",
     "validateSetMembership",
+    "MAYBE_NOTIFY",
+    "CALLBACK",
+    "INOTIFY_EVENTS",
     "RELPATH",
     "VERSION",
     "LAST_UPLOADED_URI",
@@ -54,6 +57,7 @@ from eliot import (
     ILogger,
     Message,
     Field,
+    ActionType,
     FileDestination,
     add_destinations,
     remove_destination,
@@ -89,6 +93,9 @@ from twisted.application.service import Service
 from .fileutil import (
     PathInfo,
 )
+from .fake_inotify import (
+    humanReadableMask,
+)
 
 class _GeneratorContext(object):
     def __init__(self, execution_context):
@@ -270,6 +277,27 @@ PATHINFO = Field(
     validateInstanceOf((type(None), PathInfo)),
 )
 
+INOTIFY_EVENTS = Field(
+    u"inotify_events",
+    humanReadableMask,
+    u"Details about a filesystem event generating a notification event.",
+    validateInstanceOf((int, long)),
+)
+
+MAYBE_NOTIFY = ActionType(
+    u"filesystem:notification:maybe-notify",
+    [],
+    [],
+    u"A filesystem event is being considered for dispatch to an application handler.",
+)
+
+CALLBACK = ActionType(
+    u"filesystem:notification:callback",
+    [INOTIFY_EVENTS],
+    [],
+    u"A filesystem event is being dispatched to an application callback."
+)
+
 def eliot_logging_service(reactor, destinations):
     """
     Parse the given Eliot destination descriptions and return an ``IService``

src/allmydata/windows/inotify.py

@@ -4,6 +4,12 @@
 
 import os, sys
 
+from eliot import (
+    start_action,
+    Message,
+    log_call,
+)
+
 from twisted.internet import reactor
 from twisted.internet.threads import deferToThread
 
@@ -22,6 +28,10 @@ from allmydata.util.assertutil import _assert, precondition
 from allmydata.util.encodingutil import quote_output
 from allmydata.util import log, fileutil
 from allmydata.util.pollmixin import PollMixin
+from ..util.eliotutil import (
+    MAYBE_NOTIFY,
+    CALLBACK,
+)
 
 from ctypes import WINFUNCTYPE, WinError, windll, POINTER, byref, create_string_buffer, \
     addressof, get_last_error
@@ -90,8 +100,8 @@ _action_to_inotify_mask = {
 
 INVALID_HANDLE_VALUE             = 0xFFFFFFFF
 
-TRUE  = 0
-FALSE = 1
+FALSE = 0
+TRUE = 1
 
 class Event(object):
     """
@@ -178,7 +188,7 @@ def _open_directory(path_u):
 def simple_test():
     path_u = u"test"
     filter = FILE_NOTIFY_CHANGE_FILE_NAME | FILE_NOTIFY_CHANGE_DIR_NAME | FILE_NOTIFY_CHANGE_LAST_WRITE
-    recursive = FALSE
+    recursive = TRUE
 
     hDirectory = _open_directory(path_u)
     fni = FileNotifyInformation()
@@ -189,6 +199,27 @@ def simple_test():
         for info in fni:
             print info
 
+def medium_test():
+    from twisted.python.filepath import FilePath
+
+    def print_(*event):
+        print(event)
+
+    notifier = INotify()
+    notifier.set_pending_delay(1.0)
+    IN_EXCL_UNLINK = 0x04000000L
+    mask = (  IN_CREATE
+            | IN_CLOSE_WRITE
+            | IN_MOVED_TO
+            | IN_MOVED_FROM
+            | IN_DELETE
+            | IN_ONLYDIR
+            | IN_EXCL_UNLINK
+    )
+    notifier.watch(FilePath(u"test"), mask, callbacks=[print_], recursive=True)
+    notifier.startReading()
+    reactor.run()
+
 
 NOT_STARTED = "NOT_STARTED"
 STARTED     = "STARTED"
@@ -264,8 +295,15 @@ class INotify(PollMixin):
 
             while True:
                 self._state = STARTED
+                action = start_action(
+                    action_type=u"read-changes",
+                    directory=self._path.path,
+                    recursive=self._recursive,
+                    filter=self._filter,
+                )
                 try:
-                    fni.read_changes(self._hDirectory, self._recursive, self._filter)
+                    with action:
+                        fni.read_changes(self._hDirectory, self._recursive, self._filter)
                 except WindowsError as e:
                     self._state = STOPPING
 
@@ -275,17 +313,32 @@ class INotify(PollMixin):
                     # print info
                     path = self._path.preauthChild(info.filename)  # FilePath with Unicode path
                     if info.action == FILE_ACTION_MODIFIED and path.isdir():
-                        # print "Filtering out %r" % (info,)
+                        Message.log(
+                            message_type=u"filtering-out",
+                            info=repr(info),
+                        )
                         continue
+                    else:
+                        Message.log(
+                            message_type=u"processing",
+                            info=repr(info),
+                        )
                     #mask = _action_to_inotify_mask.get(info.action, IN_CHANGED)
 
+                    @log_call(
+                        action_type=MAYBE_NOTIFY.action_type,
+                        include_args=[],
+                        include_result=False,
+                    )
                     def _do_pending_calls():
+                        event_mask = IN_CHANGED
                         self._pending_call = None
                         for path1 in self._pending:
                             if self._callbacks:
                                 for cb in self._callbacks:
                                     try:
-                                        cb(None, path1, IN_CHANGED)
+                                        with CALLBACK(inotify_events=event_mask):
+                                            cb(None, path1, event_mask)
                                     except Exception, e2:
                                         log.err(e2)
                         self._pending = set()