diff --git a/.appveyor.yml b/.appveyor.yml index c01b10912..8257fb932 100644 --- a/.appveyor.yml +++ b/.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. diff --git a/newsfragments/2997.bugfix b/newsfragments/2997.bugfix new file mode 100644 index 000000000..5b8615575 --- /dev/null +++ b/newsfragments/2997.bugfix @@ -0,0 +1 @@ +The Magic-Folder frontend is now more responsive to subtree changes on Windows. diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 48a34709f..e3d2d9ebf 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/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): diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 59e3b97cd..06962d2c5 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/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))) diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index 0dce576ce..696a66afc 100644 --- a/src/allmydata/util/eliotutil.py +++ b/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`` diff --git a/src/allmydata/windows/inotify.py b/src/allmydata/windows/inotify.py index c8805cb64..b36051690 100644 --- a/src/allmydata/windows/inotify.py +++ b/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()