From 6cd2ab79659809a243116efa09d7a6d403f0ac9d Mon Sep 17 00:00:00 2001 From: David Stainton Date: Tue, 14 Feb 2017 22:55:53 +0000 Subject: [PATCH 01/93] Add watchdog inotify and tests --- src/allmydata/frontends/magic_folder.py | 2 + src/allmydata/test/test_inotify.py | 540 ++++++++++++++++++++++++ src/allmydata/test/test_magic_folder.py | 4 +- src/allmydata/watchdog/__init__.py | 0 src/allmydata/watchdog/inotify.py | 171 ++++++++ 5 files changed, 716 insertions(+), 1 deletion(-) create mode 100644 src/allmydata/test/test_inotify.py create mode 100644 src/allmydata/watchdog/__init__.py create mode 100644 src/allmydata/watchdog/inotify.py diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index e3d2d9ebf..ff9ea59dd 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -75,6 +75,8 @@ def _get_inotify_module(): from allmydata.windows import inotify elif runtime.platform.supportsINotify(): from twisted.internet import inotify + elif sys.platform != "linux": + from allmydata.watchdog import inotify else: raise NotImplementedError("filesystem notification needed for Magic Folder is not supported.\n" "This currently requires Linux or Windows.") diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py new file mode 100644 index 000000000..0dee90f02 --- /dev/null +++ b/src/allmydata/test/test_inotify.py @@ -0,0 +1,540 @@ +# Copyright (c) Twisted Matrix Laboratories. +# See LICENSE for details. + +""" +Tests for the inotify-alike implementation L{allmydata.watchdog}. +""" + +# Note: See https://twistedmatrix.com/trac/ticket/8915 for a proposal +# to avoid all of this duplicated code from Twisted. + +import sys + +from twisted.internet import defer, reactor +from twisted.python import filepath +from twisted.trial import unittest + +# XXX todo: make these tests pass for the windows "inotify" as well. +if sys.platform != "win32": + from allmydata.frontends.magic_folder import get_inotify_module + inotify = get_inotify_module() +else: + raise NotImplementedError("inotify test suite only works on linux and mac osx, not windows.") + + +class INotifyTests(unittest.TestCase): + """ + Define all the tests for the basic functionality exposed by + L{inotify.INotify}. + """ + def setUp(self): + self.ignore_count = 0 + self.dirname = filepath.FilePath(self.mktemp()) + self.dirname.createDirectory() + self.inotify = inotify.INotify() + self.inotify.startReading() + self.addCleanup(self.inotify.stopReading) + + + def test_initializationErrors(self): + """ + L{inotify.INotify} emits a C{RuntimeError} when initialized + in an environment that doesn't support inotify as we expect it. + + We just try to raise an exception for every possible case in + the for loop in L{inotify.INotify._inotify__init__}. + """ + class FakeINotify: + def init(self): + raise inotify.INotifyError() + self.patch(inotify.INotify, '_inotify', FakeINotify()) + self.assertRaises(inotify.INotifyError, inotify.INotify) + test_initializationErrors.skip = True + + + def _notificationTest(self, mask, operation, expectedPath=None, ignore_count=0): + """ + Test notification from some filesystem operation. + + @param mask: The event mask to use when setting up the watch. + + @param operation: A function which will be called with the + name of a file in the watched directory and which should + trigger the event. + + @param expectedPath: Optionally, the name of the path which is + expected to come back in the notification event; this will + also be passed to C{operation} (primarily useful when the + operation is being done to the directory itself, not a + file in it). + + @return: A L{Deferred} which fires successfully when the + expected event has been received or fails otherwise. + """ + assert ignore_count >= 0 + if expectedPath is None: + expectedPath = self.dirname.child("foo.bar") + if ignore_count > 0: + self.ignore_count -= 1 + return + notified = defer.Deferred() + def cbNotified(result): + (watch, filename, events) = result + self.assertEqual(filename.asBytesMode(), expectedPath.asBytesMode()) + self.assertTrue(events & mask) + self.inotify.ignore(self.dirname) + notified.addCallback(cbNotified) + + def notify_event(*args): + notified.callback(args) + self.inotify.watch( + self.dirname, mask=mask, + callbacks=[notify_event]) + operation(expectedPath) + return notified + + + def test_access(self): + """ + Reading from a file in a monitored directory sends an + C{inotify.IN_ACCESS} event to the callback. + """ + def operation(path): + path.setContent(b"foo") + path.getContent() + + return self._notificationTest(inotify.IN_ACCESS, operation) + test_access.skip = True + + + def test_modify(self): + """ + Writing to a file in a monitored directory sends an + C{inotify.IN_MODIFY} event to the callback. + """ + def operation(path): + with path.open("w") as fObj: + fObj.write(b'foo') + + return self._notificationTest(inotify.IN_MODIFY, operation, ignore_count=1) + + + def test_attrib(self): + """ + Changing the metadata of a file in a monitored directory + sends an C{inotify.IN_ATTRIB} event to the callback. + """ + def operation(path): + path.touch() + path.touch() + + return self._notificationTest(inotify.IN_ATTRIB, operation, ignore_count=1) + + + def test_closeWrite(self): + """ + Closing a file which was open for writing in a monitored + directory sends an C{inotify.IN_CLOSE_WRITE} event to the + callback. + """ + def operation(path): + path.open("w").close() + + return self._notificationTest(inotify.IN_CLOSE_WRITE, operation) + + + def test_closeNoWrite(self): + """ + Closing a file which was open for reading but not writing in a + monitored directory sends an C{inotify.IN_CLOSE_NOWRITE} event + to the callback. + """ + def operation(path): + path.touch() + path.open("r").close() + + return self._notificationTest(inotify.IN_CLOSE_NOWRITE, operation) + test_closeNoWrite.skip = True + + + def test_open(self): + """ + Opening a file in a monitored directory sends an + C{inotify.IN_OPEN} event to the callback. + """ + def operation(path): + path.open("w").close() + + return self._notificationTest(inotify.IN_OPEN, operation) + test_open.skip = True + + + def test_movedFrom(self): + """ + Moving a file out of a monitored directory sends an + C{inotify.IN_MOVED_FROM} event to the callback. + """ + def operation(path): + path.open("w").close() + path.moveTo(filepath.FilePath(self.mktemp())) + + return self._notificationTest(inotify.IN_MOVED_FROM, operation) + test_movedFrom.skip = True + + + def test_movedTo(self): + """ + Moving a file into a monitored directory sends an + C{inotify.IN_MOVED_TO} event to the callback. + """ + def operation(path): + p = filepath.FilePath(self.mktemp()) + p.touch() + p.moveTo(path) + + return self._notificationTest(inotify.IN_MOVED_TO, operation) + test_movedTo.skip = True + + + def test_create(self): + """ + Creating a file in a monitored directory sends an + C{inotify.IN_CREATE} event to the callback. + """ + def operation(path): + path.open("w").close() + + return self._notificationTest(inotify.IN_CREATE, operation) + test_create.skip = True + + + def test_delete(self): + """ + Deleting a file in a monitored directory sends an + C{inotify.IN_DELETE} event to the callback. + """ + expectedPath = self.dirname.child("foo.bar") + expectedPath.touch() + notified = defer.Deferred() + def cbNotified(result): + (watch, filename, events) = result + self.assertEqual(filename.asBytesMode(), expectedPath.asBytesMode()) + self.assertTrue(events & inotify.IN_DELETE) + notified.addCallback(cbNotified) + self.inotify.watch( + self.dirname, mask=inotify.IN_DELETE, + callbacks=[lambda *args: notified.callback(args)]) + expectedPath.remove() + return notified + + + def test_deleteSelf(self): + """ + Deleting the monitored directory itself sends an + C{inotify.IN_DELETE_SELF} event to the callback. + """ + def operation(path): + path.remove() + + return self._notificationTest( + inotify.IN_DELETE_SELF, operation, expectedPath=self.dirname) + test_deleteSelf.skip = True + + + def test_moveSelf(self): + """ + Renaming the monitored directory itself sends an + C{inotify.IN_MOVE_SELF} event to the callback. + """ + def operation(path): + path.moveTo(filepath.FilePath(self.mktemp())) + + return self._notificationTest( + inotify.IN_MOVE_SELF, operation, expectedPath=self.dirname) + test_moveSelf.skip = True + + + def test_simpleSubdirectoryAutoAdd(self): + """ + L{inotify.INotify} when initialized with autoAdd==True adds + also adds the created subdirectories to the watchlist. + """ + def _callback(wp, filename, mask): + # We are notified before we actually process new + # directories, so we need to defer this check. + def _(): + try: + self.assertTrue(self.inotify._isWatched(subdir)) + d.callback(None) + except Exception: + d.errback() + reactor.callLater(0, _) + + checkMask = inotify.IN_ISDIR | inotify.IN_CREATE + self.inotify.watch( + self.dirname, mask=checkMask, autoAdd=True, + callbacks=[_callback]) + subdir = self.dirname.child('test') + d = defer.Deferred() + subdir.createDirectory() + return d + test_simpleSubdirectoryAutoAdd.skip = True + + + def test_simpleDeleteDirectory(self): + """ + L{inotify.INotify} removes a directory from the watchlist when + it's removed from the filesystem. + """ + calls = [] + def _callback(wp, filename, mask): + # We are notified before we actually process new + # directories, so we need to defer this check. + def _(): + try: + self.assertTrue(self.inotify._isWatched(subdir)) + subdir.remove() + except Exception: + d.errback() + def _eb(): + # second call, we have just removed the subdir + try: + self.assertFalse(self.inotify._isWatched(subdir)) + d.callback(None) + except Exception: + d.errback() + + if not calls: + # first call, it's the create subdir + calls.append(filename) + reactor.callLater(0, _) + + else: + reactor.callLater(0, _eb) + + checkMask = inotify.IN_ISDIR | inotify.IN_CREATE + self.inotify.watch( + self.dirname, mask=checkMask, autoAdd=True, + callbacks=[_callback]) + subdir = self.dirname.child('test') + d = defer.Deferred() + subdir.createDirectory() + return d + test_simpleDeleteDirectory.skip = True + + + def test_ignoreDirectory(self): + """ + L{inotify.INotify.ignore} removes a directory from the watchlist + """ + self.inotify.watch(self.dirname, autoAdd=True) + self.assertTrue(self.inotify._isWatched(self.dirname)) + self.inotify.ignore(self.dirname) + self.assertFalse(self.inotify._isWatched(self.dirname)) + test_ignoreDirectory.skip = True + + + def test_humanReadableMask(self): + """ + L{inotify.humaReadableMask} translates all the possible event + masks to a human readable string. + """ + for mask, value in inotify._FLAG_TO_HUMAN: + self.assertEqual(inotify.humanReadableMask(mask)[0], value) + + checkMask = ( + inotify.IN_CLOSE_WRITE | inotify.IN_ACCESS | inotify.IN_OPEN) + self.assertEqual( + set(inotify.humanReadableMask(checkMask)), + set(['close_write', 'access', 'open'])) + test_humanReadableMask.skip = True + + + def test_recursiveWatch(self): + """ + L{inotify.INotify.watch} with recursive==True will add all the + subdirectories under the given path to the watchlist. + """ + subdir = self.dirname.child('test') + subdir2 = subdir.child('test2') + subdir3 = subdir2.child('test3') + subdir3.makedirs() + dirs = [subdir, subdir2, subdir3] + self.inotify.watch(self.dirname, recursive=True) + # let's even call this twice so that we test that nothing breaks + self.inotify.watch(self.dirname, recursive=True) + for d in dirs: + self.assertTrue(self.inotify._isWatched(d)) + test_recursiveWatch.skip = True + + + def test_connectionLostError(self): + """ + L{inotify.INotify.connectionLost} if there's a problem while closing + the fd shouldn't raise the exception but should log the error + """ + import os + in_ = inotify.INotify() + os.close(in_._fd) + in_.loseConnection() + self.flushLoggedErrors() + test_connectionLostError.skip = "Based on Twisted implementation details; not relevant" + + + def test_noAutoAddSubdirectory(self): + """ + L{inotify.INotify.watch} with autoAdd==False will stop inotify + from watching subdirectories created under the watched one. + """ + def _callback(wp, fp, mask): + # We are notified before we actually process new + # directories, so we need to defer this check. + def _(): + try: + self.assertFalse(self.inotify._isWatched(subdir)) + d.callback(None) + except Exception: + d.errback() + reactor.callLater(0, _) + + checkMask = inotify.IN_ISDIR | inotify.IN_CREATE + self.inotify.watch( + self.dirname, mask=checkMask, autoAdd=False, + callbacks=[_callback]) + subdir = self.dirname.child('test') + d = defer.Deferred() + subdir.createDirectory() + return d + + + def test_seriesOfWatchAndIgnore(self): + """ + L{inotify.INotify} will watch a filepath for events even if the same + path is repeatedly added/removed/re-added to the watchpoints. + """ + expectedPath = self.dirname.child("foo.bar2") + expectedPath.touch() + + notified = defer.Deferred() + def cbNotified(result): + (ignored, filename, events) = result + self.assertEqual(filename.asBytesMode(), expectedPath.asBytesMode()) + self.assertTrue(events & inotify.IN_DELETE_SELF) + + def callIt(*args): + notified.callback(args) + + # Watch, ignore, watch again to get into the state being tested. + self.assertTrue(self.inotify.watch(expectedPath, callbacks=[callIt])) + self.inotify.ignore(expectedPath) + self.assertTrue( + self.inotify.watch( + expectedPath, mask=inotify.IN_DELETE_SELF, callbacks=[callIt])) + + notified.addCallback(cbNotified) + + # Apparently in kernel version < 2.6.25, inofify has a bug in the way + # similar events are coalesced. So, be sure to generate a different + # event here than the touch() at the top of this method might have + # generated. + expectedPath.remove() + + return notified + test_seriesOfWatchAndIgnore.skip = True + + + def test_ignoreFilePath(self): + """ + L{inotify.INotify} will ignore a filepath after it has been removed from + the watch list. + """ + expectedPath = self.dirname.child("foo.bar2") + expectedPath.touch() + expectedPath2 = self.dirname.child("foo.bar3") + expectedPath2.touch() + + notified = defer.Deferred() + def cbNotified(result): + (ignored, filename, events) = result + self.assertEqual(filename.asBytesMode(), expectedPath2.asBytesMode()) + self.assertTrue(events & inotify.IN_DELETE_SELF) + + def callIt(*args): + notified.callback(args) + + self.assertTrue( + self.inotify.watch( + expectedPath, inotify.IN_DELETE_SELF, callbacks=[callIt])) + notified.addCallback(cbNotified) + + self.assertTrue( + self.inotify.watch( + expectedPath2, inotify.IN_DELETE_SELF, callbacks=[callIt])) + + self.inotify.ignore(expectedPath) + + expectedPath.remove() + expectedPath2.remove() + + return notified + test_ignoreFilePath.skip = True + + + def test_ignoreNonWatchedFile(self): + """ + L{inotify.INotify} will raise KeyError if a non-watched filepath is + ignored. + """ + expectedPath = self.dirname.child("foo.ignored") + expectedPath.touch() + + self.assertRaises(KeyError, self.inotify.ignore, expectedPath) + test_ignoreNonWatchedFile.skip = True + + + def test_complexSubdirectoryAutoAdd(self): + """ + L{inotify.INotify} with autoAdd==True for a watched path + generates events for every file or directory already present + in a newly created subdirectory under the watched one. + + This tests that we solve a race condition in inotify even though + we may generate duplicate events. + """ + calls = set() + def _callback(wp, filename, mask): + calls.add(filename) + if len(calls) == 6: + try: + self.assertTrue(self.inotify._isWatched(subdir)) + self.assertTrue(self.inotify._isWatched(subdir2)) + self.assertTrue(self.inotify._isWatched(subdir3)) + created = someFiles + [subdir, subdir2, subdir3] + created = {f.asBytesMode() for f in created} + self.assertEqual(len(calls), len(created)) + self.assertEqual(calls, created) + except Exception: + d.errback() + else: + d.callback(None) + + checkMask = inotify.IN_ISDIR | inotify.IN_CREATE + self.inotify.watch( + self.dirname, mask=checkMask, autoAdd=True, + callbacks=[_callback]) + subdir = self.dirname.child('test') + subdir2 = subdir.child('test2') + subdir3 = subdir2.child('test3') + d = defer.Deferred() + subdir3.makedirs() + + someFiles = [subdir.child('file1.dat'), + subdir2.child('file2.dat'), + subdir3.child('file3.dat')] + # Add some files in pretty much all the directories so that we + # see that we process all of them. + for i, filename in enumerate(someFiles): + filename.setContent( + filename.path.encode(sys.getfilesystemencoding())) + return d + test_complexSubdirectoryAutoAdd.skip = "Not gonna implement autoAdd" diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 06962d2c5..b021918af 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1861,8 +1861,10 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall self.failUnlessEqual(metadata['version'], 2) def test_write_short_file(self): + d = DeferredContext(defer.succeed(None)) # Write something short enough for a LIT file. - return self._check_file(u"short", "test") + d.addCallback(lambda ign: self._check_file(u"short", "test")) + return d.result def test_magic_folder(self): d = DeferredContext(defer.succeed(None)) diff --git a/src/allmydata/watchdog/__init__.py b/src/allmydata/watchdog/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py new file mode 100644 index 000000000..666cc53f1 --- /dev/null +++ b/src/allmydata/watchdog/inotify.py @@ -0,0 +1,171 @@ + +from watchdog.observers import Observer +from watchdog.events import ( + FileSystemEventHandler, DirCreatedEvent, FileCreatedEvent, + DirDeletedEvent, FileDeletedEvent, FileModifiedEvent +) + + +from twisted.internet import reactor +from twisted.python.filepath import FilePath +from allmydata.util.fileutil import abspath_expanduser_unicode + +from allmydata.util.pollmixin import PollMixin +from allmydata.util.assertutil import _assert, precondition +from allmydata.util import log, encodingutil +from allmydata.util.fake_inotify import humanReadableMask, \ + IN_WATCH_MASK, IN_ACCESS, IN_MODIFY, IN_ATTRIB, IN_CLOSE_NOWRITE, IN_CLOSE_WRITE, \ + IN_OPEN, IN_MOVED_FROM, IN_MOVED_TO, IN_CREATE, IN_DELETE, IN_DELETE_SELF, \ + IN_MOVE_SELF, IN_UNMOUNT, IN_Q_OVERFLOW, IN_IGNORED, IN_ONLYDIR, IN_DONT_FOLLOW, \ + IN_MASK_ADD, IN_ISDIR, IN_ONESHOT, IN_CLOSE, IN_MOVED, IN_CHANGED +[humanReadableMask, \ + IN_WATCH_MASK, IN_ACCESS, IN_MODIFY, IN_ATTRIB, IN_CLOSE_NOWRITE, IN_CLOSE_WRITE, \ + IN_OPEN, IN_MOVED_FROM, IN_MOVED_TO, IN_CREATE, IN_DELETE, IN_DELETE_SELF, \ + IN_MOVE_SELF, IN_UNMOUNT, IN_Q_OVERFLOW, IN_IGNORED, IN_ONLYDIR, IN_DONT_FOLLOW, \ + IN_MASK_ADD, IN_ISDIR, IN_ONESHOT, IN_CLOSE, IN_MOVED, IN_CHANGED] + + +TRUE = 0 +FALSE = 1 + +NOT_STARTED = "NOT_STARTED" +STARTED = "STARTED" +STOPPING = "STOPPING" +STOPPED = "STOPPED" + +class INotifyEventHandler(FileSystemEventHandler): + + def __init__(self, path, mask, callbacks, pending_delay): + print "init INotifyEventHandler" + FileSystemEventHandler.__init__(self) + self._path = path + self._mask = mask + self._callbacks = callbacks + self._pending_delay = pending_delay + self._pending = set() + + def process(self, event): + print "FILESYSTEM ENCODING: %s" % encodingutil.get_filesystem_encoding() + event_filepath_u = event.src_path.decode(encodingutil.get_filesystem_encoding()) + event_filepath_u = abspath_expanduser_unicode(event_filepath_u, base=self._path) + + if event_filepath_u == self._path: + # ignore events for parent directory + return + + def _maybe_notify(path): + try: + if path in self._pending: + return + self._pending.add(path) + def _do_callbacks(): + self._pending.remove(path) + event_mask = IN_CHANGED + if isinstance(event, FileModifiedEvent): + event_mask = event_mask | IN_CLOSE_WRITE + event_mask = event_mask | IN_MODIFY + if isinstance(event, (DirCreatedEvent, FileCreatedEvent)): + event_mask = event_mask | IN_CLOSE_WRITE + if isinstance(event, (DirDeletedEvent, FileDeletedEvent)): + event_mask = event_mask | IN_DELETE + if event.is_directory: + event_mask = event_mask | IN_ISDIR + if not (self._mask & event_mask): + return + for cb in self._callbacks: + try: + cb(None, FilePath(path), event_mask) + except Exception, e: + print e + log.err(e) + _do_callbacks() + except Exception as e: + print("BAD STUFF", e) + reactor.callFromThread(_maybe_notify, event_filepath_u) + + def on_any_event(self, event): + print "PROCESS EVENT %r" % (event,) + self.process(event) + +class INotify(PollMixin): + """ + I am a prototype INotify, made to work on Mac OS X (Darwin) + using the Watchdog python library. This is actually a simplified subset + of the twisted Linux INotify class because we do not utilize the watch mask + and only implement the following methods: + - watch + - startReading + - stopReading + - wait_until_stopped + - set_pending_delay + """ + def __init__(self): + self._pending_delay = 1.0 + self.recursive_includes_new_subdirectories = False + self._observer = Observer(timeout=self._pending_delay) + self._callbacks = {} + self._watches = {} + self._state = NOT_STARTED + + def set_pending_delay(self, delay): + print "set pending delay" + assert self._state != STARTED + self._pending_delay = delay + self._observer = Observer(timeout=self._pending_delay) + + def startReading(self): + print "START READING BEGIN" + assert self._state != STARTED + try: + # XXX twisted.internet.inotify doesn't require watches to + # be set before startReading is called. + # _assert(len(self._callbacks) != 0, "no watch set") + self._observer.start() + self._state = STARTED + except Exception, e: + log.err(e) + self._state = STOPPED + raise + print "START READING END" + + def stopReading(self): + print "stopReading begin" + if self._state != STOPPED: + self._state = STOPPING + self._observer.unschedule_all() + self._observer.stop() + self._observer.join() + self._state = STOPPED + print "stopReading end" + + def wait_until_stopped(self): + print "wait until stopped" + return self.poll(lambda: self._state == STOPPED) + + def _isWatched(self, path_u): + return path_u in self._callbacks.keys() + + def ignore(self, path): + path_u = path.path + self._observer.unschedule(self._watches[path_u]) + del self._callbacks[path_u] + del self._watches[path_u] + + def watch(self, path, mask=IN_WATCH_MASK, autoAdd=False, callbacks=None, recursive=False): + precondition(isinstance(autoAdd, bool), autoAdd=autoAdd) + precondition(isinstance(recursive, bool), recursive=recursive) + assert autoAdd == False + + recursive = False + self._recursive = TRUE if recursive else FALSE + path_u = path.path + if not isinstance(path_u, unicode): + path_u = path_u.decode('utf-8') + _assert(isinstance(path_u, unicode), path_u=path_u) + + if path_u not in self._callbacks.keys(): + self._callbacks[path_u] = callbacks or [] + self._watches[path_u] = self._observer.schedule( + INotifyEventHandler(path_u, mask, self._callbacks[path_u], self._pending_delay), + path=path_u, + recursive=recursive) From 26277c218c2aa21a9b0a38aaac4b2d922ab9a869 Mon Sep 17 00:00:00 2001 From: David Stainton Date: Wed, 15 Feb 2017 20:24:58 +0000 Subject: [PATCH 02/93] Skip inotify tests on windows --- src/allmydata/test/test_inotify.py | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 0dee90f02..943865d08 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -106,7 +106,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_ACCESS, operation) test_access.skip = True - + @unittest.skipIf(sys.platform == "win32", "not supported in this library version") def test_modify(self): """ Writing to a file in a monitored directory sends an @@ -118,7 +118,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_MODIFY, operation, ignore_count=1) - + @unittest.skipIf(sys.platform == "win32", "not supported in this library version") def test_attrib(self): """ Changing the metadata of a file in a monitored directory @@ -130,7 +130,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_ATTRIB, operation, ignore_count=1) - + @unittest.skipIf(sys.platform == "win32", "not supported in this library version") def test_closeWrite(self): """ Closing a file which was open for writing in a monitored @@ -142,7 +142,6 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_CLOSE_WRITE, operation) - def test_closeNoWrite(self): """ Closing a file which was open for reading but not writing in a @@ -207,7 +206,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_CREATE, operation) test_create.skip = True - + @unittest.skipIf(sys.platform == "win32", "not supported in this library version") def test_delete(self): """ Deleting a file in a monitored directory sends an @@ -380,7 +379,7 @@ class INotifyTests(unittest.TestCase): self.flushLoggedErrors() test_connectionLostError.skip = "Based on Twisted implementation details; not relevant" - + @unittest.skipIf(sys.platform == "win32", "not supported in this library version") def test_noAutoAddSubdirectory(self): """ L{inotify.INotify.watch} with autoAdd==False will stop inotify @@ -442,7 +441,6 @@ class INotifyTests(unittest.TestCase): return notified test_seriesOfWatchAndIgnore.skip = True - def test_ignoreFilePath(self): """ L{inotify.INotify} will ignore a filepath after it has been removed from From beb84feb2df83b1e6c0e61ba77373854dfc0438a Mon Sep 17 00:00:00 2001 From: David Stainton Date: Sun, 19 Feb 2017 16:20:14 +0000 Subject: [PATCH 03/93] Fix broken test for inotify --- src/allmydata/test/test_inotify.py | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 943865d08..837bc0f6d 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -14,6 +14,8 @@ from twisted.internet import defer, reactor from twisted.python import filepath from twisted.trial import unittest +import unittest as u + # XXX todo: make these tests pass for the windows "inotify" as well. if sys.platform != "win32": from allmydata.frontends.magic_folder import get_inotify_module @@ -106,7 +108,8 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_ACCESS, operation) test_access.skip = True - @unittest.skipIf(sys.platform == "win32", "not supported in this library version") + #@unittest.skipIf(sys.platform == "win32", "not supported in this library version") + @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_modify(self): """ Writing to a file in a monitored directory sends an @@ -118,7 +121,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_MODIFY, operation, ignore_count=1) - @unittest.skipIf(sys.platform == "win32", "not supported in this library version") + @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_attrib(self): """ Changing the metadata of a file in a monitored directory @@ -130,7 +133,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_ATTRIB, operation, ignore_count=1) - @unittest.skipIf(sys.platform == "win32", "not supported in this library version") + @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_closeWrite(self): """ Closing a file which was open for writing in a monitored @@ -206,7 +209,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_CREATE, operation) test_create.skip = True - @unittest.skipIf(sys.platform == "win32", "not supported in this library version") + @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_delete(self): """ Deleting a file in a monitored directory sends an @@ -379,7 +382,7 @@ class INotifyTests(unittest.TestCase): self.flushLoggedErrors() test_connectionLostError.skip = "Based on Twisted implementation details; not relevant" - @unittest.skipIf(sys.platform == "win32", "not supported in this library version") + @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_noAutoAddSubdirectory(self): """ L{inotify.INotify.watch} with autoAdd==False will stop inotify From e0ab0db84a22f47d60e5f52bc2d92372b5e64910 Mon Sep 17 00:00:00 2001 From: David Stainton Date: Sun, 19 Feb 2017 19:59:08 +0000 Subject: [PATCH 04/93] Attempt to fix test run on windows --- src/allmydata/test/test_inotify.py | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 837bc0f6d..ab93dcba9 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -16,12 +16,9 @@ from twisted.trial import unittest import unittest as u -# XXX todo: make these tests pass for the windows "inotify" as well. -if sys.platform != "win32": - from allmydata.frontends.magic_folder import get_inotify_module - inotify = get_inotify_module() -else: - raise NotImplementedError("inotify test suite only works on linux and mac osx, not windows.") + +from allmydata.frontends.magic_folder import get_inotify_module +inotify = get_inotify_module() class INotifyTests(unittest.TestCase): From ed29b65325fde3bb850ad3ceaed08c2839565b38 Mon Sep 17 00:00:00 2001 From: David Stainton Date: Sun, 19 Feb 2017 20:38:28 +0000 Subject: [PATCH 05/93] Attempt to fix the inotify test skips --- src/allmydata/test/test_inotify.py | 18 +++++++----------- 1 file changed, 7 insertions(+), 11 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index ab93dcba9..f7dcc81a4 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -11,13 +11,11 @@ Tests for the inotify-alike implementation L{allmydata.watchdog}. import sys from twisted.internet import defer, reactor -from twisted.python import filepath +from twisted.python import filepath, runtime from twisted.trial import unittest -import unittest as u - - from allmydata.frontends.magic_folder import get_inotify_module + inotify = get_inotify_module() @@ -26,6 +24,10 @@ class INotifyTests(unittest.TestCase): Define all the tests for the basic functionality exposed by L{inotify.INotify}. """ + def skip_if_windows(self): + if runtime.platformType == "win32": + raise unittest.SkipTest("twistd does not fork under windows") + def setUp(self): self.ignore_count = 0 self.dirname = filepath.FilePath(self.mktemp()) @@ -33,7 +35,7 @@ class INotifyTests(unittest.TestCase): self.inotify = inotify.INotify() self.inotify.startReading() self.addCleanup(self.inotify.stopReading) - + self.skip_if_windows() def test_initializationErrors(self): """ @@ -105,8 +107,6 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_ACCESS, operation) test_access.skip = True - #@unittest.skipIf(sys.platform == "win32", "not supported in this library version") - @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_modify(self): """ Writing to a file in a monitored directory sends an @@ -118,7 +118,6 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_MODIFY, operation, ignore_count=1) - @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_attrib(self): """ Changing the metadata of a file in a monitored directory @@ -130,7 +129,6 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_ATTRIB, operation, ignore_count=1) - @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_closeWrite(self): """ Closing a file which was open for writing in a monitored @@ -206,7 +204,6 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_CREATE, operation) test_create.skip = True - @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_delete(self): """ Deleting a file in a monitored directory sends an @@ -379,7 +376,6 @@ class INotifyTests(unittest.TestCase): self.flushLoggedErrors() test_connectionLostError.skip = "Based on Twisted implementation details; not relevant" - @u.skipIf(sys.platform == "win32", "not supported in this library version") def test_noAutoAddSubdirectory(self): """ L{inotify.INotify.watch} with autoAdd==False will stop inotify From 806215ad99b801d54f2dc9e062ea40c7def5455a Mon Sep 17 00:00:00 2001 From: David Stainton Date: Mon, 20 Feb 2017 19:40:23 +0000 Subject: [PATCH 06/93] Fix inotify test skipping for windows --- src/allmydata/test/test_inotify.py | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index f7dcc81a4..ae3de53b1 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -24,9 +24,8 @@ class INotifyTests(unittest.TestCase): Define all the tests for the basic functionality exposed by L{inotify.INotify}. """ - def skip_if_windows(self): - if runtime.platformType == "win32": - raise unittest.SkipTest("twistd does not fork under windows") + if runtime.platformType == "win32": + skip = "inotify does not yet work on windows" def setUp(self): self.ignore_count = 0 @@ -35,7 +34,6 @@ class INotifyTests(unittest.TestCase): self.inotify = inotify.INotify() self.inotify.startReading() self.addCleanup(self.inotify.stopReading) - self.skip_if_windows() def test_initializationErrors(self): """ From 76bb84a77fa6f62ce3057abe50cf0f61b24781f1 Mon Sep 17 00:00:00 2001 From: Chris Wood Date: Wed, 25 Jul 2018 14:54:28 -0400 Subject: [PATCH 07/93] Express "watchdog" dependency via a setup.py extra For consistency with PR #388 (a06cf2ea4c966e74ad63dca2abd8a58cc2a6e33e) --- setup.py | 1 + 1 file changed, 1 insertion(+) diff --git a/setup.py b/setup.py index 3d4ccc4c0..361e2c5dc 100644 --- a/setup.py +++ b/setup.py @@ -255,6 +255,7 @@ setup(name="tahoe-lafs", # also set in __init__.py install_requires=install_requires, extras_require={ ':sys_platform=="win32"': ["pypiwin32"], + ':sys_platform!="win32" and sys_platform!="linux2"': ["watchdog"], # For magic-folder on "darwin" (macOS) and the BSDs "test": [ # Pin a specific pyflakes so we don't have different folks # disagreeing on what is or is not a lint issue. We can bump From f5ca88c1f424ca3da0b9b512e6633b12f4e6a132 Mon Sep 17 00:00:00 2001 From: Chris Wood Date: Wed, 25 Jul 2018 14:57:18 -0400 Subject: [PATCH 08/93] Fix broken conditional statement Because sys.platform will never return "linux" on python2 -- only "linux2" -- this statement will always be False. Instead, use the startswith idiom to both provide the intended behavior and ensure future compatibility with python3. --- src/allmydata/frontends/magic_folder.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index ff9ea59dd..f8758f3b8 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -75,7 +75,7 @@ def _get_inotify_module(): from allmydata.windows import inotify elif runtime.platform.supportsINotify(): from twisted.internet import inotify - elif sys.platform != "linux": + elif not sys.platform.startswith("linux"): from allmydata.watchdog import inotify else: raise NotImplementedError("filesystem notification needed for Magic Folder is not supported.\n" From c459b421b2f43eae5b8b3e493571fa2deb504e4b Mon Sep 17 00:00:00 2001 From: Chris Wood Date: Thu, 26 Jul 2018 15:34:27 -0400 Subject: [PATCH 09/93] Try debugging Travis-CI... --- src/allmydata/test/test_magic_folder.py | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index b021918af..d00500e76 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1009,7 +1009,15 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate_uploader(self.alice_magicfolder) yield alice_proc # alice uploads + from pprint import pprint + def _print_state(msg): + print("\n################### {}: ###################".format(msg)) + print(bob_proc) + print(os.path.exists(bob_fname + '.conflict')) + pprint(self.bob_magicfolder.downloader._hooks) + _print_state("before iterate_downloader()") yield iterate_downloader(self.bob_magicfolder) + _print_state("after iterate_downloader()") yield bob_proc # bob downloads # ...so now bob should produce a conflict From 720d2c67e67477f3e4b0c112c516e64918725388 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 23 Jan 2019 10:43:15 -0500 Subject: [PATCH 10/93] Change to nicer used-names idiom This avoids the pyflakes warning and tells users what they should use from the module. --- src/allmydata/watchdog/inotify.py | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index 666cc53f1..3cde376d5 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -1,11 +1,23 @@ +""" +An implementation of an inotify-like interface on top of the ``watchdog`` library. +""" + +__all__ = [ + "humanReadableMask", "INotify", + "IN_WATCH_MASK", "IN_ACCESS", "IN_MODIFY", "IN_ATTRIB", "IN_CLOSE_NOWRITE", + "IN_CLOSE_WRITE", "IN_OPEN", "IN_MOVED_FROM", "IN_MOVED_TO", "IN_CREATE", + "IN_DELETE", "IN_DELETE_SELF", "IN_MOVE_SELF", "IN_UNMOUNT", "IN_ONESHOT", + "IN_Q_OVERFLOW", "IN_IGNORED", "IN_ONLYDIR", "IN_DONT_FOLLOW", "IN_MOVED", + "IN_MASK_ADD", "IN_ISDIR", "IN_CLOSE", "IN_CHANGED", +] + from watchdog.observers import Observer from watchdog.events import ( FileSystemEventHandler, DirCreatedEvent, FileCreatedEvent, DirDeletedEvent, FileDeletedEvent, FileModifiedEvent ) - from twisted.internet import reactor from twisted.python.filepath import FilePath from allmydata.util.fileutil import abspath_expanduser_unicode @@ -18,11 +30,8 @@ from allmydata.util.fake_inotify import humanReadableMask, \ IN_OPEN, IN_MOVED_FROM, IN_MOVED_TO, IN_CREATE, IN_DELETE, IN_DELETE_SELF, \ IN_MOVE_SELF, IN_UNMOUNT, IN_Q_OVERFLOW, IN_IGNORED, IN_ONLYDIR, IN_DONT_FOLLOW, \ IN_MASK_ADD, IN_ISDIR, IN_ONESHOT, IN_CLOSE, IN_MOVED, IN_CHANGED -[humanReadableMask, \ - IN_WATCH_MASK, IN_ACCESS, IN_MODIFY, IN_ATTRIB, IN_CLOSE_NOWRITE, IN_CLOSE_WRITE, \ - IN_OPEN, IN_MOVED_FROM, IN_MOVED_TO, IN_CREATE, IN_DELETE, IN_DELETE_SELF, \ - IN_MOVE_SELF, IN_UNMOUNT, IN_Q_OVERFLOW, IN_IGNORED, IN_ONLYDIR, IN_DONT_FOLLOW, \ - IN_MASK_ADD, IN_ISDIR, IN_ONESHOT, IN_CLOSE, IN_MOVED, IN_CHANGED] + + TRUE = 0 From 3a1dcb6bf63ed3b9e3cc7abafb4729a4a88e3d01 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 23 Jan 2019 10:44:00 -0500 Subject: [PATCH 11/93] macOS should now be considered a supported platform --- src/allmydata/frontends/magic_folder.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index f8758f3b8..394a39fd4 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -79,7 +79,7 @@ def _get_inotify_module(): from allmydata.watchdog import inotify else: raise NotImplementedError("filesystem notification needed for Magic Folder is not supported.\n" - "This currently requires Linux or Windows.") + "This currently requires Linux, Windows, or macOS.") return inotify except (ImportError, AttributeError) as e: log.msg(e) From df1c30d0d907c19476c8df13a6622f3c9f602752 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 29 Jan 2019 09:22:27 -0500 Subject: [PATCH 12/93] consistent whitespace --- src/allmydata/test/test_inotify.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index ae3de53b1..2549696cc 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -35,6 +35,7 @@ class INotifyTests(unittest.TestCase): self.inotify.startReading() self.addCleanup(self.inotify.stopReading) + def test_initializationErrors(self): """ L{inotify.INotify} emits a C{RuntimeError} when initialized @@ -116,6 +117,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_MODIFY, operation, ignore_count=1) + def test_attrib(self): """ Changing the metadata of a file in a monitored directory @@ -127,6 +129,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_ATTRIB, operation, ignore_count=1) + def test_closeWrite(self): """ Closing a file which was open for writing in a monitored @@ -138,6 +141,7 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_CLOSE_WRITE, operation) + def test_closeNoWrite(self): """ Closing a file which was open for reading but not writing in a From c57a70dbec9e748cf1aedf08e190c06e9ffb8220 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 29 Jan 2019 09:40:49 -0500 Subject: [PATCH 13/93] remove skipped tests for behavior we obviously don't care about --- src/allmydata/test/test_inotify.py | 54 ------------------------------ 1 file changed, 54 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 2549696cc..09d55fc12 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -36,22 +36,6 @@ class INotifyTests(unittest.TestCase): self.addCleanup(self.inotify.stopReading) - def test_initializationErrors(self): - """ - L{inotify.INotify} emits a C{RuntimeError} when initialized - in an environment that doesn't support inotify as we expect it. - - We just try to raise an exception for every possible case in - the for loop in L{inotify.INotify._inotify__init__}. - """ - class FakeINotify: - def init(self): - raise inotify.INotifyError() - self.patch(inotify.INotify, '_inotify', FakeINotify()) - self.assertRaises(inotify.INotifyError, inotify.INotify) - test_initializationErrors.skip = True - - def _notificationTest(self, mask, operation, expectedPath=None, ignore_count=0): """ Test notification from some filesystem operation. @@ -94,18 +78,6 @@ class INotifyTests(unittest.TestCase): return notified - def test_access(self): - """ - Reading from a file in a monitored directory sends an - C{inotify.IN_ACCESS} event to the callback. - """ - def operation(path): - path.setContent(b"foo") - path.getContent() - - return self._notificationTest(inotify.IN_ACCESS, operation) - test_access.skip = True - def test_modify(self): """ Writing to a file in a monitored directory sends an @@ -142,32 +114,6 @@ class INotifyTests(unittest.TestCase): return self._notificationTest(inotify.IN_CLOSE_WRITE, operation) - def test_closeNoWrite(self): - """ - Closing a file which was open for reading but not writing in a - monitored directory sends an C{inotify.IN_CLOSE_NOWRITE} event - to the callback. - """ - def operation(path): - path.touch() - path.open("r").close() - - return self._notificationTest(inotify.IN_CLOSE_NOWRITE, operation) - test_closeNoWrite.skip = True - - - def test_open(self): - """ - Opening a file in a monitored directory sends an - C{inotify.IN_OPEN} event to the callback. - """ - def operation(path): - path.open("w").close() - - return self._notificationTest(inotify.IN_OPEN, operation) - test_open.skip = True - - def test_movedFrom(self): """ Moving a file out of a monitored directory sends an From 2cfa88265bd0d8dfc6bab4b8894bb544ed739b30 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 29 Jan 2019 10:14:00 -0500 Subject: [PATCH 14/93] Turns out we don't care about IN_CREATE either --- src/allmydata/test/test_inotify.py | 11 ----------- src/allmydata/watchdog/inotify.py | 1 + 2 files changed, 1 insertion(+), 11 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 09d55fc12..977fa472e 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -141,17 +141,6 @@ class INotifyTests(unittest.TestCase): test_movedTo.skip = True - def test_create(self): - """ - Creating a file in a monitored directory sends an - C{inotify.IN_CREATE} event to the callback. - """ - def operation(path): - path.open("w").close() - - return self._notificationTest(inotify.IN_CREATE, operation) - test_create.skip = True - def test_delete(self): """ Deleting a file in a monitored directory sends an diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index 3cde376d5..92020273e 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -74,6 +74,7 @@ class INotifyEventHandler(FileSystemEventHandler): event_mask = event_mask | IN_CLOSE_WRITE event_mask = event_mask | IN_MODIFY if isinstance(event, (DirCreatedEvent, FileCreatedEvent)): + # For our purposes, IN_CREATE is irrelevant. event_mask = event_mask | IN_CLOSE_WRITE if isinstance(event, (DirDeletedEvent, FileDeletedEvent)): event_mask = event_mask | IN_DELETE From e0c5905a7e522c79942f7650e76c4e7aaf0b4843 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 29 Jan 2019 10:31:02 -0500 Subject: [PATCH 15/93] Fix the move skips. And explain them. --- src/allmydata/test/test_inotify.py | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 977fa472e..32d8b92c8 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -124,7 +124,11 @@ class INotifyTests(unittest.TestCase): path.moveTo(filepath.FilePath(self.mktemp())) return self._notificationTest(inotify.IN_MOVED_FROM, operation) - test_movedFrom.skip = True + # The watchdog implementation makes it difficult to get this event. Also, + # the magic-folder implementation doesn't really *need* exactly this + # event. It would be nice to get some event on move, which watchdog gives + # us. But this test is overly specific for our purposes. + test_movedFrom.skip = "not available on watchdog" def test_movedTo(self): @@ -138,7 +142,8 @@ class INotifyTests(unittest.TestCase): p.moveTo(path) return self._notificationTest(inotify.IN_MOVED_TO, operation) - test_movedTo.skip = True + # Ditto the comment on test_movedFrom about watchdog here. + test_movedTo.skip = "not available on watchdog" def test_delete(self): From 19400cc13d9e9d47bddcf6caa784e3d8dadda407 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 29 Jan 2019 10:31:46 -0500 Subject: [PATCH 16/93] Neither of these events is used --- src/allmydata/test/test_inotify.py | 26 -------------------------- 1 file changed, 26 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 32d8b92c8..893f44044 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -166,32 +166,6 @@ class INotifyTests(unittest.TestCase): return notified - def test_deleteSelf(self): - """ - Deleting the monitored directory itself sends an - C{inotify.IN_DELETE_SELF} event to the callback. - """ - def operation(path): - path.remove() - - return self._notificationTest( - inotify.IN_DELETE_SELF, operation, expectedPath=self.dirname) - test_deleteSelf.skip = True - - - def test_moveSelf(self): - """ - Renaming the monitored directory itself sends an - C{inotify.IN_MOVE_SELF} event to the callback. - """ - def operation(path): - path.moveTo(filepath.FilePath(self.mktemp())) - - return self._notificationTest( - inotify.IN_MOVE_SELF, operation, expectedPath=self.dirname) - test_moveSelf.skip = True - - def test_simpleSubdirectoryAutoAdd(self): """ L{inotify.INotify} when initialized with autoAdd==True adds From 5273a930aa8bfec8f3f45f2fd3097542063eaaec Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 29 Jan 2019 10:32:58 -0500 Subject: [PATCH 17/93] magic-folder doesn't use autoAdd=True --- src/allmydata/test/test_inotify.py | 27 --------------------------- 1 file changed, 27 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 893f44044..80cc43686 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -166,33 +166,6 @@ class INotifyTests(unittest.TestCase): return notified - def test_simpleSubdirectoryAutoAdd(self): - """ - L{inotify.INotify} when initialized with autoAdd==True adds - also adds the created subdirectories to the watchlist. - """ - def _callback(wp, filename, mask): - # We are notified before we actually process new - # directories, so we need to defer this check. - def _(): - try: - self.assertTrue(self.inotify._isWatched(subdir)) - d.callback(None) - except Exception: - d.errback() - reactor.callLater(0, _) - - checkMask = inotify.IN_ISDIR | inotify.IN_CREATE - self.inotify.watch( - self.dirname, mask=checkMask, autoAdd=True, - callbacks=[_callback]) - subdir = self.dirname.child('test') - d = defer.Deferred() - subdir.createDirectory() - return d - test_simpleSubdirectoryAutoAdd.skip = True - - def test_simpleDeleteDirectory(self): """ L{inotify.INotify} removes a directory from the watchlist when From 006342d7d4d968f0cfa6c1b04d42d8f8b8d2f2b8 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 29 Jan 2019 10:33:33 -0500 Subject: [PATCH 18/93] magic-folder doesn't use ignore --- src/allmydata/test/test_inotify.py | 95 ------------------------------ 1 file changed, 95 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 80cc43686..7ce973ea1 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -208,17 +208,6 @@ class INotifyTests(unittest.TestCase): test_simpleDeleteDirectory.skip = True - def test_ignoreDirectory(self): - """ - L{inotify.INotify.ignore} removes a directory from the watchlist - """ - self.inotify.watch(self.dirname, autoAdd=True) - self.assertTrue(self.inotify._isWatched(self.dirname)) - self.inotify.ignore(self.dirname) - self.assertFalse(self.inotify._isWatched(self.dirname)) - test_ignoreDirectory.skip = True - - def test_humanReadableMask(self): """ L{inotify.humaReadableMask} translates all the possible event @@ -291,90 +280,6 @@ class INotifyTests(unittest.TestCase): return d - def test_seriesOfWatchAndIgnore(self): - """ - L{inotify.INotify} will watch a filepath for events even if the same - path is repeatedly added/removed/re-added to the watchpoints. - """ - expectedPath = self.dirname.child("foo.bar2") - expectedPath.touch() - - notified = defer.Deferred() - def cbNotified(result): - (ignored, filename, events) = result - self.assertEqual(filename.asBytesMode(), expectedPath.asBytesMode()) - self.assertTrue(events & inotify.IN_DELETE_SELF) - - def callIt(*args): - notified.callback(args) - - # Watch, ignore, watch again to get into the state being tested. - self.assertTrue(self.inotify.watch(expectedPath, callbacks=[callIt])) - self.inotify.ignore(expectedPath) - self.assertTrue( - self.inotify.watch( - expectedPath, mask=inotify.IN_DELETE_SELF, callbacks=[callIt])) - - notified.addCallback(cbNotified) - - # Apparently in kernel version < 2.6.25, inofify has a bug in the way - # similar events are coalesced. So, be sure to generate a different - # event here than the touch() at the top of this method might have - # generated. - expectedPath.remove() - - return notified - test_seriesOfWatchAndIgnore.skip = True - - def test_ignoreFilePath(self): - """ - L{inotify.INotify} will ignore a filepath after it has been removed from - the watch list. - """ - expectedPath = self.dirname.child("foo.bar2") - expectedPath.touch() - expectedPath2 = self.dirname.child("foo.bar3") - expectedPath2.touch() - - notified = defer.Deferred() - def cbNotified(result): - (ignored, filename, events) = result - self.assertEqual(filename.asBytesMode(), expectedPath2.asBytesMode()) - self.assertTrue(events & inotify.IN_DELETE_SELF) - - def callIt(*args): - notified.callback(args) - - self.assertTrue( - self.inotify.watch( - expectedPath, inotify.IN_DELETE_SELF, callbacks=[callIt])) - notified.addCallback(cbNotified) - - self.assertTrue( - self.inotify.watch( - expectedPath2, inotify.IN_DELETE_SELF, callbacks=[callIt])) - - self.inotify.ignore(expectedPath) - - expectedPath.remove() - expectedPath2.remove() - - return notified - test_ignoreFilePath.skip = True - - - def test_ignoreNonWatchedFile(self): - """ - L{inotify.INotify} will raise KeyError if a non-watched filepath is - ignored. - """ - expectedPath = self.dirname.child("foo.ignored") - expectedPath.touch() - - self.assertRaises(KeyError, self.inotify.ignore, expectedPath) - test_ignoreNonWatchedFile.skip = True - - def test_complexSubdirectoryAutoAdd(self): """ L{inotify.INotify} with autoAdd==True for a watched path From 37cb9a1284ecc0f9d75fabdf64ae7a549673a4e2 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 29 Jan 2019 10:40:51 -0500 Subject: [PATCH 19/93] Fix the directory deletion test --- src/allmydata/test/test_inotify.py | 40 ++++++++++++------------------ 1 file changed, 16 insertions(+), 24 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 7ce973ea1..6ac7f362d 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -171,41 +171,33 @@ class INotifyTests(unittest.TestCase): L{inotify.INotify} removes a directory from the watchlist when it's removed from the filesystem. """ - calls = [] + subdir = self.dirname.child('test') + subdir.createDirectory() + + d = defer.Deferred() + def _callback(wp, filename, mask): - # We are notified before we actually process new - # directories, so we need to defer this check. + # We are notified before the watch state is updated so we need to + # delay our check of that watch state a bit. def _(): - try: - self.assertTrue(self.inotify._isWatched(subdir)) - subdir.remove() - except Exception: - d.errback() - def _eb(): - # second call, we have just removed the subdir try: self.assertFalse(self.inotify._isWatched(subdir)) d.callback(None) except Exception: d.errback() - - if not calls: - # first call, it's the create subdir - calls.append(filename) - reactor.callLater(0, _) - - else: - reactor.callLater(0, _eb) + reactor.callLater(0, _) checkMask = inotify.IN_ISDIR | inotify.IN_CREATE self.inotify.watch( - self.dirname, mask=checkMask, autoAdd=True, - callbacks=[_callback]) - subdir = self.dirname.child('test') - d = defer.Deferred() - subdir.createDirectory() + self.dirname, + mask=checkMask, + callbacks=[_callback], + recursive=True, + ) + self.assertTrue(self.inotify._isWatched(subdir)) + subdir.remove() + return d - test_simpleDeleteDirectory.skip = True def test_humanReadableMask(self): From 76a6f2d7104142dad63329a78affa19be8e6433b Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 29 Jan 2019 10:42:00 -0500 Subject: [PATCH 20/93] Why skip it? It works. --- src/allmydata/test/test_inotify.py | 1 - 1 file changed, 1 deletion(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 6ac7f362d..007bb0475 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -213,7 +213,6 @@ class INotifyTests(unittest.TestCase): self.assertEqual( set(inotify.humanReadableMask(checkMask)), set(['close_write', 'access', 'open'])) - test_humanReadableMask.skip = True def test_recursiveWatch(self): From 75d77305f93f4adbfa1d98c84583a0dee90423cc Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 10:14:26 -0500 Subject: [PATCH 21/93] avoid using a bool for a skip value --- src/allmydata/test/test_inotify.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 007bb0475..ea8c90315 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -230,7 +230,7 @@ class INotifyTests(unittest.TestCase): self.inotify.watch(self.dirname, recursive=True) for d in dirs: self.assertTrue(self.inotify._isWatched(d)) - test_recursiveWatch.skip = True + test_recursiveWatch.skip = "not relevant" def test_connectionLostError(self): From fa3a48b39ee4856483f9b79ddbeaad33307c5b89 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 10:21:36 -0500 Subject: [PATCH 22/93] news fragment --- newsfragments/1432.feature | 1 + 1 file changed, 1 insertion(+) create mode 100644 newsfragments/1432.feature diff --git a/newsfragments/1432.feature b/newsfragments/1432.feature new file mode 100644 index 000000000..2bb9a8b01 --- /dev/null +++ b/newsfragments/1432.feature @@ -0,0 +1 @@ +Magic-Folders are now supported on macOS. From 7cbfc07b0cccabd9562d6289f524f26b80f8c633 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 10:28:07 -0500 Subject: [PATCH 23/93] expunge low-grade debugging change --- src/allmydata/test/test_magic_folder.py | 8 -------- 1 file changed, 8 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index d00500e76..b021918af 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1009,15 +1009,7 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate_uploader(self.alice_magicfolder) yield alice_proc # alice uploads - from pprint import pprint - def _print_state(msg): - print("\n################### {}: ###################".format(msg)) - print(bob_proc) - print(os.path.exists(bob_fname + '.conflict')) - pprint(self.bob_magicfolder.downloader._hooks) - _print_state("before iterate_downloader()") yield iterate_downloader(self.bob_magicfolder) - _print_state("after iterate_downloader()") yield bob_proc # bob downloads # ...so now bob should produce a conflict From bda7301cb84a527b75f2be7e573cd6f7877a65e0 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 11:05:24 -0500 Subject: [PATCH 24/93] [wip] convert logging to eliot --- src/allmydata/watchdog/inotify.py | 149 +++++++++++++++++------------- 1 file changed, 87 insertions(+), 62 deletions(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index 92020273e..da2bf18c5 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -22,18 +22,24 @@ from twisted.internet import reactor from twisted.python.filepath import FilePath from allmydata.util.fileutil import abspath_expanduser_unicode +from eliot import ( + ActionType, + MessageType, + Message, + Field, + preserve_context, + start_action, +) + from allmydata.util.pollmixin import PollMixin from allmydata.util.assertutil import _assert, precondition -from allmydata.util import log, encodingutil +from allmydata.util import encodingutil from allmydata.util.fake_inotify import humanReadableMask, \ IN_WATCH_MASK, IN_ACCESS, IN_MODIFY, IN_ATTRIB, IN_CLOSE_NOWRITE, IN_CLOSE_WRITE, \ IN_OPEN, IN_MOVED_FROM, IN_MOVED_TO, IN_CREATE, IN_DELETE, IN_DELETE_SELF, \ IN_MOVE_SELF, IN_UNMOUNT, IN_Q_OVERFLOW, IN_IGNORED, IN_ONLYDIR, IN_DONT_FOLLOW, \ IN_MASK_ADD, IN_ISDIR, IN_ONESHOT, IN_CLOSE, IN_MOVED, IN_CHANGED - - - TRUE = 0 FALSE = 1 @@ -42,10 +48,34 @@ STARTED = "STARTED" STOPPING = "STOPPING" STOPPED = "STOPPED" -class INotifyEventHandler(FileSystemEventHandler): +_PATH = Field.for_types( + u"path", + [bytes, unicode], + u"The path an inotify event concerns.", +) +MAYBE_NOTIFY = ActionType( + u"watchdog:inotify:maybe-notify", + [], + [], + u"An inotify event is being considered for dispatch to an application handler.", +) + +ANY_INOTIFY_EVENT = ActionType( + u"watchdog:inotify:any-event", + [_PATH], + [], + u"An inotify event is being dispatched.", +) + +CALLBACK = MessageType( + u"watchdog:inotify:callback", + [], + u"An inotify event is being dispatched to an application callback." +) + +class INotifyEventHandler(FileSystemEventHandler): def __init__(self, path, mask, callbacks, pending_delay): - print "init INotifyEventHandler" FileSystemEventHandler.__init__(self) self._path = path self._mask = mask @@ -53,8 +83,31 @@ class INotifyEventHandler(FileSystemEventHandler): self._pending_delay = pending_delay self._pending = set() + def _maybe_notify(self, path, event): + with MAYBE_NOTIFY(): + event_mask = IN_CHANGED + if isinstance(event, FileModifiedEvent): + event_mask = event_mask | IN_CLOSE_WRITE + event_mask = event_mask | IN_MODIFY + if isinstance(event, (DirCreatedEvent, FileCreatedEvent)): + # For our purposes, IN_CREATE is irrelevant. + event_mask = event_mask | IN_CLOSE_WRITE + if isinstance(event, (DirDeletedEvent, FileDeletedEvent)): + event_mask = event_mask | IN_DELETE + if event.is_directory: + event_mask = event_mask | IN_ISDIR + if not (self._mask & event_mask): + return + for cb in self._callbacks: + try: + with CALLBACK(): + cb(None, FilePath(path), event_mask) + except: + # Eliot already logged the exception for us. + # There's nothing else we can do about it here. + pass + def process(self, event): - print "FILESYSTEM ENCODING: %s" % encodingutil.get_filesystem_encoding() event_filepath_u = event.src_path.decode(encodingutil.get_filesystem_encoding()) event_filepath_u = abspath_expanduser_unicode(event_filepath_u, base=self._path) @@ -62,40 +115,16 @@ class INotifyEventHandler(FileSystemEventHandler): # ignore events for parent directory return - def _maybe_notify(path): - try: - if path in self._pending: - return - self._pending.add(path) - def _do_callbacks(): - self._pending.remove(path) - event_mask = IN_CHANGED - if isinstance(event, FileModifiedEvent): - event_mask = event_mask | IN_CLOSE_WRITE - event_mask = event_mask | IN_MODIFY - if isinstance(event, (DirCreatedEvent, FileCreatedEvent)): - # For our purposes, IN_CREATE is irrelevant. - event_mask = event_mask | IN_CLOSE_WRITE - if isinstance(event, (DirDeletedEvent, FileDeletedEvent)): - event_mask = event_mask | IN_DELETE - if event.is_directory: - event_mask = event_mask | IN_ISDIR - if not (self._mask & event_mask): - return - for cb in self._callbacks: - try: - cb(None, FilePath(path), event_mask) - except Exception, e: - print e - log.err(e) - _do_callbacks() - except Exception as e: - print("BAD STUFF", e) - reactor.callFromThread(_maybe_notify, event_filepath_u) + reactor.callFromThread( + preserve_context(self._maybe_notify), + event_filepath_u, + event, + ) def on_any_event(self, event): - print "PROCESS EVENT %r" % (event,) - self.process(event) + with ANY_INOTIFY_EVENT(path=self._path): + self.process(event) + class INotify(PollMixin): """ @@ -118,38 +147,34 @@ class INotify(PollMixin): self._state = NOT_STARTED def set_pending_delay(self, delay): - print "set pending delay" + Message.log(message_type=u"watchdog:inotify:set-pending-delay", delay=delay) assert self._state != STARTED self._pending_delay = delay self._observer = Observer(timeout=self._pending_delay) def startReading(self): - print "START READING BEGIN" - assert self._state != STARTED - try: - # XXX twisted.internet.inotify doesn't require watches to - # be set before startReading is called. - # _assert(len(self._callbacks) != 0, "no watch set") - self._observer.start() - self._state = STARTED - except Exception, e: - log.err(e) - self._state = STOPPED - raise - print "START READING END" + with start_action(action_type=u"watchdog:inotify:start-reading"): + assert self._state != STARTED + try: + # XXX twisted.internet.inotify doesn't require watches to + # be set before startReading is called. + # _assert(len(self._callbacks) != 0, "no watch set") + self._observer.start() + self._state = STARTED + except: + self._state = STOPPED + raise def stopReading(self): - print "stopReading begin" - if self._state != STOPPED: - self._state = STOPPING - self._observer.unschedule_all() - self._observer.stop() - self._observer.join() - self._state = STOPPED - print "stopReading end" + with start_action(action_type=u"watchdog:inotify:stop-reading"): + if self._state != STOPPED: + self._state = STOPPING + self._observer.unschedule_all() + self._observer.stop() + self._observer.join() + self._state = STOPPED def wait_until_stopped(self): - print "wait until stopped" return self.poll(lambda: self._state == STOPPED) def _isWatched(self, path_u): From e822d438081ea0409f620eab096df9e5e67641b7 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 11:23:10 -0500 Subject: [PATCH 25/93] add more detailed logging to this test --- src/allmydata/test/test_magic_folder.py | 79 +++++++++++++++++++------ 1 file changed, 60 insertions(+), 19 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index b021918af..afad76253 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1020,38 +1020,79 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea alice_fname = os.path.join(self.alice_magic_dir, 'localchange1') bob_fname = os.path.join(self.bob_magic_dir, 'localchange1') - # alice creates a file, bob downloads it alice_proc = self.alice_magicfolder.uploader.set_hook('processed') bob_proc = self.bob_magicfolder.downloader.set_hook('processed') - yield self.alice_fileops.write(alice_fname, 'contents0\n') - yield iterate(self.alice_magicfolder) # for windows + with start_action(action_type=u"alice:create"): + yield self.alice_fileops.write(alice_fname, 'contents0\n') + yield iterate(self.alice_magicfolder) # for windows - yield iterate_uploader(self.alice_magicfolder) - yield alice_proc # alice uploads + with start_action(action_type=u"alice:upload"): + yield iterate_uploader(self.alice_magicfolder) + yield alice_proc # alice uploads + self.assertEqual( + 1, + self._get_count( + 'uploader.files_uploaded', + client=self.alice_magicfolder._client, + ), + ) - yield iterate_downloader(self.bob_magicfolder) - yield bob_proc # bob downloads + with start_action(action_type=u"bob:download"): + yield iterate_downloader(self.bob_magicfolder) + yield bob_proc # bob downloads + self.assertEqual( + 1, + self._get_count( + 'downloader.objects_downloaded', + client=self.bob_magicfolder._client, + ), + ) - # alice creates a new change alice_proc = self.alice_magicfolder.uploader.set_hook('processed') bob_proc = self.bob_magicfolder.downloader.set_hook('processed') - yield self.alice_fileops.write(alice_fname, 'contents1\n') - yield iterate(self.alice_magicfolder) # for windows + with start_action(action_type=u"alice:rewrite"): + yield self.alice_fileops.write(alice_fname, 'contents1\n') + yield iterate(self.alice_magicfolder) # for windows - # before bob downloads, make a local change - with open(bob_fname, "w") as f: - f.write("bob's local change") + with start_action(action_type=u"bob:rewrite"): + # before bob downloads, make a local change + with open(bob_fname, "w") as f: + f.write("bob's local change") - yield iterate_uploader(self.alice_magicfolder) - yield alice_proc # alice uploads + with start_action(action_type=u"alice:reupload"): + yield iterate_uploader(self.alice_magicfolder) + yield alice_proc # alice uploads + self.assertEqual( + 2, + self._get_count( + 'uploader.files_uploaded', + client=self.alice_magicfolder._client, + ), + ) - yield iterate_downloader(self.bob_magicfolder) - yield bob_proc # bob downloads + with start_action(action_type=u"bob:redownload-and-conflict"): + yield iterate_downloader(self.bob_magicfolder) + yield bob_proc # bob downloads - # ...so now bob should produce a conflict - self.assertTrue(os.path.exists(bob_fname + '.conflict')) + self.assertEqual( + 2, + self._get_count( + 'downloader.objects_downloaded', + client=self.bob_magicfolder._client, + ), + ) + self.assertEqual( + 1, + self._get_count( + 'downloader.objects_conflicted', + client=self.bob_magicfolder._client, + ), + ) + + # ...so now bob should produce a conflict + self.assertTrue(os.path.exists(bob_fname + '.conflict')) @inline_callbacks def test_alice_delete_and_restore(self): From 6ccd9f4b448b5861c247e347a88ca8f799b83830 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 11:47:59 -0500 Subject: [PATCH 26/93] try to get some indication of fake behavior in the log --- src/allmydata/util/fake_inotify.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/allmydata/util/fake_inotify.py b/src/allmydata/util/fake_inotify.py index 15893243a..45d360105 100644 --- a/src/allmydata/util/fake_inotify.py +++ b/src/allmydata/util/fake_inotify.py @@ -74,6 +74,8 @@ def humanReadableMask(mask): return s +from eliot import start_action + # This class is not copied from Twisted; it acts as a mock. class INotify(object): def startReading(self): @@ -89,8 +91,9 @@ class INotify(object): self.callbacks = callbacks def event(self, filepath, mask): - for cb in self.callbacks: - cb(None, filepath, mask) + with start_action(action_type=u"fake-inotify:event", path=filepath.path, mask=mask): + for cb in self.callbacks: + cb(None, filepath, mask) __all__ = ["INotify", "humanReadableMask", "IN_WATCH_MASK", "IN_ACCESS", From 331b96250dcae6c2a51afda3a60727aae1ec968e Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 11:58:04 -0500 Subject: [PATCH 27/93] Space out file modifications to fit within macOS constraints --- src/allmydata/test/test_magic_folder.py | 34 +++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index afad76253..a0a61acfb 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -3,8 +3,10 @@ import os, sys, time import stat, shutil, json import mock from os.path import join, exists, isdir +from errno import ENOENT from twisted.internet import defer, task, reactor +from twisted.python.runtime import platform from twisted.python.filepath import FilePath from testtools import ( @@ -73,6 +75,37 @@ else: support_missing = False support_message = None +if platform.isMacOSX(): + def modified_mtime_barrier(path): + """ + macOS filesystem (HFS+) has one second resolution on filesystem + modification time metadata. Make sure that code running after this + function which modifies the file will produce a changed mtime on that + file. + """ + try: + mtime = path.getModificationTime() + except OSError as e: + if e.errno == ENOENT: + # If the file does not exist yet, there is no current mtime + # value that might match a future mtime value. We have + # nothing to do. + return + # Propagate any other errors as we don't know what's going on. + raise + if int(time.time()) == int(mtime): + # The current time matches the file's modification time, to the + # resolution of the filesystem metadata. Therefore, change the + # current time. + time.sleep(1) +else: + def modified_mtime_barrier(path): + """ + non-macOS platforms have sufficiently high-resolution file modification + time metadata that nothing in particular is required to ensure a + modified mtime as a result of a future write. + """ + class NewConfigUtilTests(SyncTestCase): @@ -563,6 +596,7 @@ class FileOperationsHelper(object): d = notify_when_pending(self._uploader, path_u) + modified_mtime_barrier(FilePath(fname)) with open(fname, "wb") as f: f.write(contents) From 1883cee37f5e66c12f0a93ab6dda146fdd2d2cd1 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 12:48:33 -0500 Subject: [PATCH 28/93] speed up these failures --- src/allmydata/test/test_magic_folder.py | 1 + 1 file changed, 1 insertion(+) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index a0a61acfb..9e5f7f81b 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -2204,6 +2204,7 @@ class RealTest(SingleMagicFolderTestMixin, AsyncTestCase): class RealTestAliceBob(MagicFolderAliceBobTestMixin, AsyncTestCase): """This is skipped unless both Twisted and the platform support inotify.""" inject_inotify = False + timeout = 15 def setUp(self): d = super(RealTestAliceBob, self).setUp() From 3b5e8d7e6b6810d2aac7926e367d497eb732edcd Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 13:05:21 -0500 Subject: [PATCH 29/93] move inotify events eliot field --- src/allmydata/frontends/magic_folder.py | 14 ++------------ 1 file changed, 2 insertions(+), 12 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 394a39fd4..ade9f7505 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -35,9 +35,6 @@ from allmydata.util import ( yamlutil, eliotutil, ) -from allmydata.util.fake_inotify import ( - humanReadableMask, -) from allmydata.interfaces import IDirectoryNode from allmydata.util import log from allmydata.util.fileutil import ( @@ -690,13 +687,6 @@ NOTIFIED = ActionType( u"Magic-Folder received a notification of a local filesystem change for a certain path.", ) -_EVENTS = Field( - u"events", - humanReadableMask, - u"Details about a filesystem event generating a notification event.", - eliotutil.validateInstanceOf((int, long)), -) - _NON_DIR_CREATED = Field.for_types( u"non_dir_created", [bool], @@ -706,7 +696,7 @@ _NON_DIR_CREATED = Field.for_types( REACT_TO_INOTIFY = ActionType( u"magic-folder:react-to-inotify", - [_EVENTS], + [eliotutil.INOTIFY_EVENTS], [_IGNORED, _NON_DIR_CREATED, _ALREADY_PENDING], u"Magic-Folder is processing a notification from inotify(7) (or a clone) about a filesystem event.", ) @@ -1260,7 +1250,7 @@ class Uploader(QueueMixin): # All can do is id() or repr() it and neither of those actually # produces very illuminating results. We drop opaque on the # floor, anyway. - events=events_mask, + inotify_events=events_mask, ) success_fields = dict(non_dir_created=False, already_pending=False, ignored=False) From 1ec0e484224b1473e61e069c0b68929edbcd5124 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 13:05:34 -0500 Subject: [PATCH 30/93] good housekeeping --- src/allmydata/watchdog/inotify.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index da2bf18c5..11752b69a 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -3,6 +3,13 @@ An implementation of an inotify-like interface on top of the ``watchdog`` library. """ +from __future__ import ( + unicode_literals, + print_function, + absolute_import, + division, +) + __all__ = [ "humanReadableMask", "INotify", "IN_WATCH_MASK", "IN_ACCESS", "IN_MODIFY", "IN_ATTRIB", "IN_CLOSE_NOWRITE", From b19e7c59460a6a5f11261bfe12098ae6e484fe88 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 13:06:20 -0500 Subject: [PATCH 31/93] fix and improve callback logging --- src/allmydata/watchdog/inotify.py | 23 ++++++++++++++++++----- 1 file changed, 18 insertions(+), 5 deletions(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index 11752b69a..a83f25aa7 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -21,6 +21,7 @@ __all__ = [ from watchdog.observers import Observer from watchdog.events import ( + FileSystemEvent, FileSystemEventHandler, DirCreatedEvent, FileCreatedEvent, DirDeletedEvent, FileDeletedEvent, FileModifiedEvent ) @@ -31,7 +32,6 @@ from allmydata.util.fileutil import abspath_expanduser_unicode from eliot import ( ActionType, - MessageType, Message, Field, preserve_context, @@ -47,6 +47,11 @@ from allmydata.util.fake_inotify import humanReadableMask, \ IN_MOVE_SELF, IN_UNMOUNT, IN_Q_OVERFLOW, IN_IGNORED, IN_ONLYDIR, IN_DONT_FOLLOW, \ IN_MASK_ADD, IN_ISDIR, IN_ONESHOT, IN_CLOSE, IN_MOVED, IN_CHANGED +from ..util.eliotutil import ( + INOTIFY_EVENTS, + validateInstanceOf, +) + TRUE = 0 FALSE = 1 @@ -68,15 +73,23 @@ MAYBE_NOTIFY = ActionType( u"An inotify event is being considered for dispatch to an application handler.", ) +_EVENT = Field( + u"event", + lambda e: e.event_type, + u"The watchdog event that has taken place.", + validateInstanceOf(FileSystemEvent), +) + ANY_INOTIFY_EVENT = ActionType( u"watchdog:inotify:any-event", - [_PATH], + [_PATH, _EVENT], [], u"An inotify event is being dispatched.", ) -CALLBACK = MessageType( +CALLBACK = ActionType( u"watchdog:inotify:callback", + [INOTIFY_EVENTS], [], u"An inotify event is being dispatched to an application callback." ) @@ -107,7 +120,7 @@ class INotifyEventHandler(FileSystemEventHandler): return for cb in self._callbacks: try: - with CALLBACK(): + with CALLBACK(inotify_events=event_mask): cb(None, FilePath(path), event_mask) except: # Eliot already logged the exception for us. @@ -129,7 +142,7 @@ class INotifyEventHandler(FileSystemEventHandler): ) def on_any_event(self, event): - with ANY_INOTIFY_EVENT(path=self._path): + with ANY_INOTIFY_EVENT(path=self._path, event=event): self.process(event) From 53318203253f77b69e54fd27b0b9726e94bbf745 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 13:43:46 -0500 Subject: [PATCH 32/93] Put some Eliot here --- src/allmydata/test/cli/test_magic_folder.py | 73 +++++++++++++++++---- 1 file changed, 60 insertions(+), 13 deletions(-) diff --git a/src/allmydata/test/cli/test_magic_folder.py b/src/allmydata/test/cli/test_magic_folder.py index 6556b063f..7704f8a33 100644 --- a/src/allmydata/test/cli/test_magic_folder.py +++ b/src/allmydata/test/cli/test_magic_folder.py @@ -6,6 +6,10 @@ import re import time from datetime import datetime +from eliot import ( + log_call, + start_action, +) from eliot.twisted import ( DeferredContext, ) @@ -38,7 +42,13 @@ class MagicFolderCLITestMixin(CLITestMixin, GridTestMixin, NonASCIIPathMixin): self.bob_nickname = self.unicode_or_fallback(u"Bob\u00F8", u"Bob", io_as_well=True) def do_create_magic_folder(self, client_num): - d = self.do_cli("magic-folder", "--debug", "create", "magic:", client_num=client_num) + with start_action(action_type=u"create-magic-folder", client_num=client_num).context(): + d = DeferredContext( + self.do_cli( + "magic-folder", "--debug", "create", "magic:", + client_num=client_num, + ) + ) def _done((rc,stdout,stderr)): self.failUnlessEqual(rc, 0, stdout + stderr) self.assertIn("Alias 'magic' created", stdout) @@ -49,16 +59,30 @@ class MagicFolderCLITestMixin(CLITestMixin, GridTestMixin, NonASCIIPathMixin): self.assertIn("magic", aliases) self.failUnless(aliases["magic"].startswith("URI:DIR2:")) d.addCallback(_done) - return d + return d.addActionFinish() def do_invite(self, client_num, nickname): nickname_arg = unicode_to_argv(nickname) - d = self.do_cli("magic-folder", "invite", "magic:", nickname_arg, client_num=client_num) + action = start_action( + action_type=u"invite-to-magic-folder", + client_num=client_num, + nickname=nickname, + ) + with action.context(): + d = DeferredContext( + self.do_cli( + "magic-folder", + "invite", + "magic:", + nickname_arg, + client_num=client_num, + ) + ) def _done((rc, stdout, stderr)): self.failUnlessEqual(rc, 0) return (rc, stdout, stderr) d.addCallback(_done) - return d + return d.addActionFinish() def do_list(self, client_num, json=False): args = ("magic-folder", "list",) @@ -81,18 +105,32 @@ class MagicFolderCLITestMixin(CLITestMixin, GridTestMixin, NonASCIIPathMixin): return d def do_join(self, client_num, local_dir, invite_code): - precondition(isinstance(local_dir, unicode), local_dir=local_dir) - precondition(isinstance(invite_code, str), invite_code=invite_code) - - local_dir_arg = unicode_to_argv(local_dir) - d = self.do_cli("magic-folder", "join", invite_code, local_dir_arg, client_num=client_num) + action = start_action( + action_type=u"join-magic-folder", + client_num=client_num, + local_dir=local_dir, + invite_code=invite_code, + ) + with action.context(): + precondition(isinstance(local_dir, unicode), local_dir=local_dir) + precondition(isinstance(invite_code, str), invite_code=invite_code) + local_dir_arg = unicode_to_argv(local_dir) + d = DeferredContext( + self.do_cli( + "magic-folder", + "join", + invite_code, + local_dir_arg, + client_num=client_num, + ) + ) def _done((rc, stdout, stderr)): self.failUnlessEqual(rc, 0) self.failUnlessEqual(stdout, "") self.failUnlessEqual(stderr, "") return (rc, stdout, stderr) d.addCallback(_done) - return d + return d.addActionFinish() def do_leave(self, client_num): d = self.do_cli("magic-folder", "leave", client_num=client_num) @@ -106,8 +144,16 @@ class MagicFolderCLITestMixin(CLITestMixin, GridTestMixin, NonASCIIPathMixin): """Tests that our collective directory has the readonly cap of our upload directory. """ - collective_readonly_cap = self.get_caps_from_files(client_num)[0] - d = self.do_cli("ls", "--json", collective_readonly_cap, client_num=client_num) + action = start_action(action_type=u"check-joined-config") + with action.context(): + collective_readonly_cap = self.get_caps_from_files(client_num)[0] + d = DeferredContext( + self.do_cli( + "ls", "--json", + collective_readonly_cap, + client_num=client_num, + ) + ) def _done((rc, stdout, stderr)): self.failUnlessEqual(rc, 0) return (rc, stdout, stderr) @@ -118,7 +164,7 @@ class MagicFolderCLITestMixin(CLITestMixin, GridTestMixin, NonASCIIPathMixin): self.failUnless(s is not None) return None d.addCallback(test_joined_magic_folder) - return d + return d.addActionFinish() def get_caps_from_files(self, client_num): from allmydata.frontends.magic_folder import load_magic_folders @@ -126,6 +172,7 @@ class MagicFolderCLITestMixin(CLITestMixin, GridTestMixin, NonASCIIPathMixin): mf = folders["default"] return mf['collective_dircap'], mf['upload_dircap'] + @log_call def check_config(self, client_num, local_dir): client_config = fileutil.read(os.path.join(self.get_clientdir(i=client_num), "tahoe.cfg")) mf_yaml = fileutil.read(os.path.join(self.get_clientdir(i=client_num), "private", "magic_folders.yaml")) From 679b9a93c1825edcb5f3b5a77323acbf9eebabac Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 13:58:48 -0500 Subject: [PATCH 33/93] this is a chunk of work I guess --- src/allmydata/test/test_magic_folder.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 9e5f7f81b..4f28b290a 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -717,7 +717,8 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea temp = self.mktemp() self.basedir = abspath_expanduser_unicode(temp.decode(get_filesystem_encoding())) # set_up_grid depends on self.basedir existing - self.set_up_grid(num_clients=2, oneshare=True) + with start_action(action_type=u"set_up_grid"): + self.set_up_grid(num_clients=2, oneshare=True) self.alice_clock = task.Clock() self.bob_clock = task.Clock() From 725c85b2f42fd2ecb43e45e2f8b644a55fb39993 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 14:54:45 -0500 Subject: [PATCH 34/93] try not creating a duplicate Observer --- src/allmydata/frontends/magic_folder.py | 11 +++++++++-- src/allmydata/watchdog/inotify.py | 3 +-- 2 files changed, 10 insertions(+), 4 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index ade9f7505..7a24c2070 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1144,8 +1144,14 @@ class Uploader(QueueMixin): | self._inotify.IN_ONLYDIR | IN_EXCL_UNLINK ) - self._notifier.watch(self._local_filepath, mask=self.mask, callbacks=[self._notify], - recursive=True) + + def _add_watch(self): + self._notifier.watch( + self._local_filepath, + mask=self.mask, + callbacks=[self._notify], + recursive=True, + ) def start_monitoring(self): action = START_MONITORING(**self._log_fields) @@ -1153,6 +1159,7 @@ class Uploader(QueueMixin): d = DeferredContext(defer.succeed(None)) d.addCallback(lambda ign: self._notifier.startReading()) + d.addCallback(lambda ign: self._add_watch()) d.addCallback(lambda ign: self._count('dirs_monitored')) d.addBoth(self._call_hook, 'started') return d.addActionFinish() diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index a83f25aa7..75055a678 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -161,7 +161,6 @@ class INotify(PollMixin): def __init__(self): self._pending_delay = 1.0 self.recursive_includes_new_subdirectories = False - self._observer = Observer(timeout=self._pending_delay) self._callbacks = {} self._watches = {} self._state = NOT_STARTED @@ -170,7 +169,6 @@ class INotify(PollMixin): Message.log(message_type=u"watchdog:inotify:set-pending-delay", delay=delay) assert self._state != STARTED self._pending_delay = delay - self._observer = Observer(timeout=self._pending_delay) def startReading(self): with start_action(action_type=u"watchdog:inotify:start-reading"): @@ -179,6 +177,7 @@ class INotify(PollMixin): # XXX twisted.internet.inotify doesn't require watches to # be set before startReading is called. # _assert(len(self._callbacks) != 0, "no watch set") + self._observer = Observer(timeout=self._pending_delay) self._observer.start() self._state = STARTED except: From fdd603e42d74d82a803385064e4cd0c9c3c4a9d0 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 15:08:10 -0500 Subject: [PATCH 35/93] keep everything in the test context --- src/allmydata/test/test_magic_folder.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 4f28b290a..4697dacb4 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1208,7 +1208,7 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea # the other tests in here should get their own minimal test-case. @skipIf(sys.platform == "win32", "Still inotify problems on Windows (FIXME)") def test_alice_bob(self): - d = defer.succeed(None) + d = DeferredContext(defer.succeed(None)) # XXX FIXME just quickly porting this test via aliases -- the # "real" solution is to break out any relevant test-cases as @@ -1555,8 +1555,7 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder)) d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 3, magic=self.alice_magicfolder)) - - return d + return d.addActionFinish() test_alice_bob.timeout = 300 From 0845c9ba809d159cc60f150107e653c8618618b6 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 15:08:26 -0500 Subject: [PATCH 36/93] no apparent reason for ths --- src/allmydata/test/test_magic_folder.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 4697dacb4..33b32e4d3 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1557,8 +1557,6 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 3, magic=self.alice_magicfolder)) return d.addActionFinish() - test_alice_bob.timeout = 300 - class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, ReallyEqualMixin, CheckerMixin): """ From 2d5f1757122e20bc9e041f6ccc4133eeb9eed335 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 15:37:52 -0500 Subject: [PATCH 37/93] this is probably more useful and less surprising --- src/allmydata/watchdog/inotify.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index 75055a678..d65a0014a 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -142,7 +142,7 @@ class INotifyEventHandler(FileSystemEventHandler): ) def on_any_event(self, event): - with ANY_INOTIFY_EVENT(path=self._path, event=event): + with ANY_INOTIFY_EVENT(path=event.src_path, event=event): self.process(event) From 49c5a1f8d53720fa99b3e3807ca4ae02dc3ee928 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 27 Feb 2019 15:44:18 -0500 Subject: [PATCH 38/93] remove harmless but irrelevant noise --- src/allmydata/watchdog/inotify.py | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index d65a0014a..b28b9d1f4 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -52,9 +52,6 @@ from ..util.eliotutil import ( validateInstanceOf, ) -TRUE = 0 -FALSE = 1 - NOT_STARTED = "NOT_STARTED" STARTED = "STARTED" STOPPING = "STOPPING" @@ -210,8 +207,6 @@ class INotify(PollMixin): precondition(isinstance(recursive, bool), recursive=recursive) assert autoAdd == False - recursive = False - self._recursive = TRUE if recursive else FALSE path_u = path.path if not isinstance(path_u, unicode): path_u = path_u.decode('utf-8') @@ -222,4 +217,5 @@ class INotify(PollMixin): self._watches[path_u] = self._observer.schedule( INotifyEventHandler(path_u, mask, self._callbacks[path_u], self._pending_delay), path=path_u, - recursive=recursive) + recursive=False, + ) From 9d65b5c1558e2f34011abc28a2a055c8319984d8 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 28 Feb 2019 08:25:39 -0500 Subject: [PATCH 39/93] Get back to the reactor thread sooner --- src/allmydata/watchdog/inotify.py | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index b28b9d1f4..eaa74c95f 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -132,15 +132,14 @@ class INotifyEventHandler(FileSystemEventHandler): # ignore events for parent directory return - reactor.callFromThread( - preserve_context(self._maybe_notify), - event_filepath_u, - event, - ) + self._maybe_notify(event_filepath_u, event) def on_any_event(self, event): with ANY_INOTIFY_EVENT(path=event.src_path, event=event): - self.process(event) + reactor.callFromThread( + preserve_context(self.process), + event, + ) class INotify(PollMixin): From f38f53c28d17cb33d0c69f3c0105ff63ece9c290 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 28 Feb 2019 08:44:19 -0500 Subject: [PATCH 40/93] Add some more action context to this test --- src/allmydata/test/test_magic_folder.py | 125 ++++++++++++++---------- 1 file changed, 74 insertions(+), 51 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 33b32e4d3..2c8fa4374 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -796,75 +796,98 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea bob_fname = os.path.join(self.bob_magic_dir, 'blam') alice_proc = self.alice_magicfolder.uploader.set_hook('processed') - yield self.alice_fileops.write(alice_fname, 'contents0\n') - yield iterate(self.alice_magicfolder) # for windows - # alice uploads - yield iterate_uploader(self.alice_magicfolder) - yield alice_proc + with start_action(action_type=u"alice:create"): + yield self.alice_fileops.write(alice_fname, 'contents0\n') + yield iterate(self.alice_magicfolder) # for windows - yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 0) - yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 0) + with start_action(action_type=u"alice:upload"): + yield iterate_uploader(self.alice_magicfolder) + yield alice_proc - # bob downloads - yield iterate_downloader(self.bob_magicfolder) + with start_action(action_type=u"alice:check-upload"): + yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 0) + yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 0) + + with start_action(action_type=u"bob:download"): + yield iterate_downloader(self.bob_magicfolder) + + with start_action(action_type=u"alice:recheck-upload"): + yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 0) + yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 0) + + with start_action(action_type=u"bob:check-download"): + yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 0) + yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 0) + yield self.failUnlessReallyEqual( + self._get_count('downloader.objects_failed', client=self.bob_magicfolder._client), + 0 + ) + yield self.failUnlessReallyEqual( + self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client), + 1 + ) + + yield iterate(self.bob_magicfolder) # for windows - # check the state - yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 0) - yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 0) - yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 0) - yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 0) - yield self.failUnlessReallyEqual( - self._get_count('downloader.objects_failed', client=self.bob_magicfolder._client), - 0 - ) - yield self.failUnlessReallyEqual( - self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client), - 1 - ) - yield iterate(self.bob_magicfolder) # for windows - # now bob deletes it (bob should upload, alice download) bob_proc = self.bob_magicfolder.uploader.set_hook('processed') alice_proc = self.alice_magicfolder.downloader.set_hook('processed') - yield self.bob_fileops.delete(bob_fname) - yield iterate(self.bob_magicfolder) # for windows - yield iterate_uploader(self.bob_magicfolder) - yield bob_proc - yield iterate_downloader(self.alice_magicfolder) - yield alice_proc + with start_action(action_type=u"bob:delete"): + yield self.bob_fileops.delete(bob_fname) + yield iterate(self.bob_magicfolder) # for windows + + with start_action(action_type=u"bob:upload"): + yield iterate_uploader(self.bob_magicfolder) + yield bob_proc + + with start_action(action_type=u"alice:download"): + yield iterate_downloader(self.alice_magicfolder) + yield alice_proc # check versions - node, metadata = yield self.alice_magicfolder.downloader._get_collective_latest_file(u'blam') - self.assertTrue(metadata['deleted']) - yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 1) - yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 1) - yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 1) - yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 1) + with start_action(action_type=u"bob:check-upload"): + node, metadata = yield self.alice_magicfolder.downloader._get_collective_latest_file(u'blam') + self.assertTrue(metadata['deleted']) + yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 1) + yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 1) - # not *entirely* sure why we need to iterate Alice for the - # real test here. But, we do. - yield iterate(self.alice_magicfolder) + with start_action(action_type=u"alice:check-download"): + yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 1) + yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 1) + + with start_action(action_type=u"alice:mysterious-iterate"): + # not *entirely* sure why we need to iterate Alice for the + # real test here. But, we do. + yield iterate(self.alice_magicfolder) # now alice restores it (alice should upload, bob download) alice_proc = self.alice_magicfolder.uploader.set_hook('processed') bob_proc = self.bob_magicfolder.downloader.set_hook('processed') - yield self.alice_fileops.write(alice_fname, 'new contents\n') - yield iterate(self.alice_magicfolder) # for windows - yield iterate_uploader(self.alice_magicfolder) - yield alice_proc - yield iterate_downloader(self.bob_magicfolder) - yield bob_proc + with start_action(action_type=u"alice:rewrite"): + yield self.alice_fileops.write(alice_fname, 'new contents\n') + yield iterate(self.alice_magicfolder) # for windows + + with start_action(action_type=u"alice:reupload"): + yield iterate_uploader(self.alice_magicfolder) + yield alice_proc + + with start_action(action_type=u"bob:redownload"): + yield iterate_downloader(self.bob_magicfolder) + yield bob_proc # check versions - node, metadata = yield self.alice_magicfolder.downloader._get_collective_latest_file(u'blam') - self.assertTrue('deleted' not in metadata or not metadata['deleted']) - yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 2) - yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 2) - yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 2) - yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 2) + with start_action(action_type=u"bob:recheck-download"): + node, metadata = yield self.alice_magicfolder.downloader._get_collective_latest_file(u'blam') + self.assertTrue('deleted' not in metadata or not metadata['deleted']) + yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 2) + yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 2) + + with start_action(action_type=u"alice:final-check-upload"): + yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 2) + yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 2) @inline_callbacks def test_alice_sees_bobs_delete_with_error(self): From 2d2b8a4b7f375f522d0ac7c396b84e0481397b51 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 28 Feb 2019 08:51:31 -0500 Subject: [PATCH 41/93] eliot this too --- src/allmydata/test/test_magic_folder.py | 86 +++++++++++++++---------- 1 file changed, 51 insertions(+), 35 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 2c8fa4374..ecec41c28 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -900,52 +900,68 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea alice_proc = self.alice_magicfolder.uploader.set_hook('processed') bob_proc = self.bob_magicfolder.downloader.set_hook('processed') - yield self.alice_fileops.write(alice_fname, 'contents0\n') - yield iterate(self.alice_magicfolder) # for windows + with start_action(action_type=u"alice:create"): + yield self.alice_fileops.write(alice_fname, 'contents0\n') + yield iterate(self.alice_magicfolder) # for windows - yield iterate_uploader(self.alice_magicfolder) - yield alice_proc # alice uploads + with start_action(action_type=u"alice:upload"): + yield iterate_uploader(self.alice_magicfolder) + yield alice_proc # alice uploads - yield iterate_downloader(self.bob_magicfolder) - yield bob_proc # bob downloads + with start_action(action_type=u"bob:download"): + yield iterate_downloader(self.bob_magicfolder) + yield bob_proc # bob downloads - yield iterate(self.alice_magicfolder) # for windows - yield iterate(self.bob_magicfolder) # for windows + with start_action(action_type=u"mysterious:iterate"): + yield iterate(self.alice_magicfolder) # for windows + yield iterate(self.bob_magicfolder) # for windows # check the state (XXX I had to switch the versions to 0; is that really right? why?) - yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 0) - yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 0) - yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 0) - yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 0) - self.failUnlessReallyEqual( - self._get_count('downloader.objects_failed', client=self.bob_magicfolder._client), - 0 - ) - self.failUnlessReallyEqual( - self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client), - 1 - ) + with start_action(action_type=u"alice:check"): + yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 0) + yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 0) + + with start_action(action_type=u"bob:check"): + yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 0) + yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 0) + self.failUnlessReallyEqual( + self._get_count('downloader.objects_failed', client=self.bob_magicfolder._client), + 0 + ) + self.failUnlessReallyEqual( + self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client), + 1 + ) - # now bob deletes it (bob should upload, alice download) bob_proc = self.bob_magicfolder.uploader.set_hook('processed') alice_proc = self.alice_magicfolder.downloader.set_hook('processed') - yield self.bob_fileops.delete(bob_fname) - # just after notifying bob, we also delete alice's, - # covering the 'except' flow in _rename_deleted_file() - yield self.alice_fileops.delete(alice_fname) - yield iterate_uploader(self.bob_magicfolder) - yield bob_proc - yield iterate_downloader(self.alice_magicfolder) - yield alice_proc + with start_action(action_type=u"bob:delete"): + yield self.bob_fileops.delete(bob_fname) + + with start_action(action_type=u"alice:delete"): + # just after notifying bob, we also delete alice's, + # covering the 'except' flow in _rename_deleted_file() + yield self.alice_fileops.delete(alice_fname) + + with start_action(action_type=u"bob:upload-delete"): + yield iterate_uploader(self.bob_magicfolder) + yield bob_proc + + with start_action(action_type=u"alice:download-delete"): + yield iterate_downloader(self.alice_magicfolder) + yield alice_proc # check versions - node, metadata = yield self.alice_magicfolder.downloader._get_collective_latest_file(u'blam') - self.assertTrue(metadata['deleted']) - yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 1) - yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 1) - yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 1) - yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 1) + with start_action(action_type=u"bob:check"): + node, metadata = yield self.alice_magicfolder.downloader._get_collective_latest_file(u'blam') + self.assertTrue(metadata['deleted']) + yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 1) + yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 1) + + with start_action(action_type=u"alice:check"): + yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 1) + yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 1) @inline_callbacks def test_alice_create_bob_update(self): From 5d4564ad517121ea774782e4f270fef3360b80de Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 28 Feb 2019 08:55:57 -0500 Subject: [PATCH 42/93] and this test --- src/allmydata/test/test_magic_folder.py | 122 +++++++++++++----------- 1 file changed, 68 insertions(+), 54 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index ecec41c28..46f611466 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1177,71 +1177,85 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea alice_proc = self.alice_magicfolder.uploader.set_hook('processed') bob_proc = self.bob_magicfolder.downloader.set_hook('processed') - yield self.alice_fileops.write(alice_fname, 'contents0\n') - yield iterate(self.alice_magicfolder) # for windows + with start_action(action_type=u"alice:create"): + yield self.alice_fileops.write(alice_fname, 'contents0\n') + yield iterate(self.alice_magicfolder) # for windows - yield iterate_uploader(self.alice_magicfolder) - yield alice_proc # alice uploads + with start_action(action_type=u"alice:upload"): + yield iterate_uploader(self.alice_magicfolder) + yield alice_proc # alice uploads - yield iterate_downloader(self.bob_magicfolder) - yield bob_proc # bob downloads + with start_action(action_type=u"bob:download"): + yield iterate_downloader(self.bob_magicfolder) + yield bob_proc # bob downloads - # check the state - yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 0) - yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 0) - yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 0) - yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 0) - yield self.failUnlessReallyEqual( - self._get_count('downloader.objects_failed', client=self.bob_magicfolder._client), - 0 - ) - yield self.failUnlessReallyEqual( - self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client), - 1 - ) - self.failUnless(os.path.exists(bob_fname)) - self.failUnless(not os.path.exists(bob_fname + '.backup')) - self.failUnless(not os.path.exists(bob_fname + '.conflict')) + with start_action(action_type=u"alice:check"): + yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 0) + yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 0) + + with start_action(action_type=u"bob:check"): + yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 0) + yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 0) + yield self.failUnlessReallyEqual( + self._get_count('downloader.objects_failed', client=self.bob_magicfolder._client), + 0 + ) + yield self.failUnlessReallyEqual( + self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client), + 1 + ) + self.failUnless(os.path.exists(bob_fname)) + self.failUnless(not os.path.exists(bob_fname + '.backup')) + self.failUnless(not os.path.exists(bob_fname + '.conflict')) - # now alice deletes it (alice should upload, bob download) alice_proc = self.alice_magicfolder.uploader.set_hook('processed') bob_proc = self.bob_magicfolder.downloader.set_hook('processed') - yield self.alice_fileops.delete(alice_fname) - yield iterate_uploader(self.alice_magicfolder) - yield alice_proc - yield iterate_downloader(self.bob_magicfolder) - yield bob_proc + with start_action(action_type=u"alice:delete"): + yield self.alice_fileops.delete(alice_fname) + yield iterate_uploader(self.alice_magicfolder) + yield alice_proc - # check the state - yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 1) - yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 1) - yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 1) - yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 1) - self.assertFalse(os.path.exists(bob_fname)) - self.assertTrue(os.path.exists(bob_fname + '.backup')) - self.assertFalse(os.path.exists(bob_fname + '.conflict')) + with start_action(action_type=u"bob:redownload"): + yield iterate_downloader(self.bob_magicfolder) + yield bob_proc - # now alice restores the file (with new contents) - os.unlink(bob_fname + '.backup') - alice_proc = self.alice_magicfolder.uploader.set_hook('processed') - bob_proc = self.bob_magicfolder.downloader.set_hook('processed') - yield self.alice_fileops.write(alice_fname, 'alice wuz here\n') - yield iterate(self.alice_magicfolder) # for windows + with start_action(action_type=u"bob:recheck"): + yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 1) + yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 1) + self.assertFalse(os.path.exists(bob_fname)) + self.assertTrue(os.path.exists(bob_fname + '.backup')) + self.assertFalse(os.path.exists(bob_fname + '.conflict')) - yield iterate_uploader(self.alice_magicfolder) - yield iterate_downloader(self.alice_magicfolder) # why? - yield alice_proc - yield iterate_downloader(self.bob_magicfolder) - yield iterate_uploader(self.bob_magicfolder) - yield bob_proc + with start_action(action_type=u"alice:recheck"): + yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 1) + yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 1) - # check the state - yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 2) - yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 2) - yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 2) - yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 2) - self.failUnless(os.path.exists(bob_fname)) + with start_action(action_type=u"alice:restore"): + os.unlink(bob_fname + '.backup') + alice_proc = self.alice_magicfolder.uploader.set_hook('processed') + bob_proc = self.bob_magicfolder.downloader.set_hook('processed') + yield self.alice_fileops.write(alice_fname, 'alice wuz here\n') + yield iterate(self.alice_magicfolder) # for windows + + with start_action(action_type=u"alice:reupload"): + yield iterate_uploader(self.alice_magicfolder) + yield iterate_downloader(self.alice_magicfolder) # why? + yield alice_proc + + with start_action(action_type=u"bob:final-redownload"): + yield iterate_downloader(self.bob_magicfolder) + yield iterate_uploader(self.bob_magicfolder) + yield bob_proc + + with start_action(action_type=u"bob:final-check"): + yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 2) + yield self._check_version_in_local_db(self.bob_magicfolder, u"blam", 2) + self.failUnless(os.path.exists(bob_fname)) + + with start_action(action_type=u"alice:final-check"): + yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 2) + yield self._check_version_in_local_db(self.alice_magicfolder, u"blam", 2) # XXX this should be shortened -- as in, any cases not covered by # the other tests in here should get their own minimal test-case. From c63a75dd2adbc953d1560a14ddd03e132f360119 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 28 Feb 2019 12:15:39 -0500 Subject: [PATCH 43/93] Tag some of test_alice_bob with Eliot actions --- src/allmydata/test/test_magic_folder.py | 302 ++++++++++++++---------- 1 file changed, 171 insertions(+), 131 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 46f611466..e692355f6 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -22,6 +22,7 @@ from testtools.matchers import ( from eliot import ( Message, start_action, + log_call, ) from eliot.twisted import DeferredContext @@ -1310,22 +1311,24 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate(self.alice_magicfolder) d.addCallback(_wait_for, Alice_to_write_a_file) - d.addCallback(lambda ign: self._check_version_in_dmd(self.alice_magicfolder, u"file1", 0)) - d.addCallback(lambda ign: self._check_version_in_local_db(self.alice_magicfolder, u"file1", 0)) - d.addCallback(lambda ign: self._check_uploader_count('objects_failed', 0)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 1)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 1)) - d.addCallback(lambda ign: self._check_uploader_count('objects_queued', 0)) - d.addCallback(lambda ign: self._check_uploader_count('directories_created', 0)) - d.addCallback(lambda ign: self._check_uploader_count('objects_conflicted', 0)) - d.addCallback(lambda ign: self._check_uploader_count('objects_conflicted', 0, magic=self.bob_magicfolder)) + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.alice_magicfolder, u"file1", 0) + self._check_version_in_local_db(self.alice_magicfolder, u"file1", 0) + self._check_uploader_count('objects_failed', 0) + self._check_uploader_count('objects_succeeded', 1) + self._check_uploader_count('files_uploaded', 1) + self._check_uploader_count('objects_queued', 0) + self._check_uploader_count('directories_created', 0) + self._check_uploader_count('objects_conflicted', 0) + self._check_uploader_count('objects_conflicted', 0, magic=self.bob_magicfolder) - d.addCallback(lambda ign: self._check_version_in_local_db(self.bob_magicfolder, u"file1", 0)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 1)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 0, magic=self.bob_magicfolder)) -# d.addCallback(lambda ign: self._check_uploader_count('objects_not_uploaded', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 1, magic=self.bob_magicfolder)) + self._check_version_in_local_db(self.bob_magicfolder, u"file1", 0) + self._check_downloader_count('objects_failed', 0) + self._check_downloader_count('objects_downloaded', 1) + self._check_uploader_count('objects_succeeded', 0, magic=self.bob_magicfolder) + self._check_downloader_count('objects_downloaded', 1, magic=self.bob_magicfolder) + d.addCallback(check_state) @inline_callbacks def Alice_to_delete_file(): @@ -1346,19 +1349,21 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate(self.bob_magicfolder) d.addCallback(notify_bob_moved) - d.addCallback(lambda ign: self._check_version_in_dmd(self.alice_magicfolder, u"file1", 1)) - d.addCallback(lambda ign: self._check_version_in_local_db(self.alice_magicfolder, u"file1", 1)) - d.addCallback(lambda ign: self._check_uploader_count('objects_failed', 0)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 2)) -# d.addCallback(lambda ign: self._check_uploader_count('objects_not_uploaded', 1, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 0, magic=self.bob_magicfolder)) + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.alice_magicfolder, u"file1", 1) + self._check_version_in_local_db(self.alice_magicfolder, u"file1", 1) + self._check_uploader_count('objects_failed', 0) + self._check_uploader_count('objects_succeeded', 2) + self._check_uploader_count('objects_succeeded', 0, magic=self.bob_magicfolder) - d.addCallback(lambda ign: self._check_version_in_local_db(self.bob_magicfolder, u"file1", 1)) - d.addCallback(lambda ign: self._check_version_in_dmd(self.bob_magicfolder, u"file1", 1)) - d.addCallback(lambda ign: self._check_file_gone(self.bob_magicfolder, u"file1")) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 2)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 2, magic=self.bob_magicfolder)) + self._check_version_in_local_db(self.bob_magicfolder, u"file1", 1) + self._check_version_in_dmd(self.bob_magicfolder, u"file1", 1) + self._check_file_gone(self.bob_magicfolder, u"file1") + self._check_downloader_count('objects_failed', 0) + self._check_downloader_count('objects_downloaded', 2) + self._check_downloader_count('objects_downloaded', 2, magic=self.bob_magicfolder) + d.addCallback(check_state) @inline_callbacks def Alice_to_rewrite_file(): @@ -1370,24 +1375,26 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea ) yield iterate(self.alice_magicfolder) d.addCallback(_wait_for, Alice_to_rewrite_file) - d.addCallback(lambda ign: iterate(self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_version_in_dmd(self.alice_magicfolder, u"file1", 2)) - d.addCallback(lambda ign: self._check_version_in_local_db(self.alice_magicfolder, u"file1", 2)) - d.addCallback(lambda ign: self._check_uploader_count('objects_failed', 0)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 3)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 3)) - d.addCallback(lambda ign: self._check_uploader_count('objects_queued', 0)) - d.addCallback(lambda ign: self._check_uploader_count('directories_created', 0)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0)) - d.addCallback(lambda ign: self._check_version_in_dmd(self.bob_magicfolder, u"file1", 2)) - d.addCallback(lambda ign: self._check_version_in_local_db(self.bob_magicfolder, u"file1", 2)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 3)) -# d.addCallback(lambda ign: self._check_uploader_count('objects_not_uploaded', 1, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 0, magic=self.bob_magicfolder)) + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.alice_magicfolder, u"file1", 2) + self._check_version_in_local_db(self.alice_magicfolder, u"file1", 2) + self._check_uploader_count('objects_failed', 0) + self._check_uploader_count('objects_succeeded', 3) + self._check_uploader_count('files_uploaded', 3) + self._check_uploader_count('objects_queued', 0) + self._check_uploader_count('directories_created', 0) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_conflicted', 0) + + self._check_version_in_dmd(self.bob_magicfolder, u"file1", 2) + self._check_version_in_local_db(self.bob_magicfolder, u"file1", 2) + self._check_downloader_count('objects_failed', 0) + self._check_downloader_count('objects_downloaded', 3) + self._check_uploader_count('objects_succeeded', 0, magic=self.bob_magicfolder) + d.addCallback(check_state) path_u = u"/tmp/magic_folder_test" encoded_path_u = magicpath.path2magic(u"/tmp/magic_folder_test") @@ -1408,12 +1415,14 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea return d2 d.addCallback(Alice_tries_to_p0wn_Bob) - d.addCallback(lambda ign: self.failIf(os.path.exists(path_u))) - d.addCallback(lambda ign: self._check_version_in_local_db(self.bob_magicfolder, encoded_path_u, None)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 3)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0)) -# d.addCallback(lambda ign: self._check_uploader_count('objects_not_uploaded', 2, magic=self.bob_magicfolder)) + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self.failIf(os.path.exists(path_u)) + self._check_version_in_local_db(self.bob_magicfolder, encoded_path_u, None) + self._check_downloader_count('objects_downloaded', 3) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_conflicted', 0) + d.addCallback(check_state) @inline_callbacks def Bob_to_rewrite_file(): @@ -1424,21 +1433,23 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate(self.bob_magicfolder) d.addCallback(lambda ign: _wait_for(None, Bob_to_rewrite_file, alice=False)) - d.addCallback(lambda ign: self._check_version_in_dmd(self.bob_magicfolder, u"file1", 3)) - d.addCallback(lambda ign: self._check_version_in_local_db(self.bob_magicfolder, u"file1", 3)) -# d.addCallback(lambda ign: self._check_uploader_count('objects_not_uploaded', 1, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 1, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 1, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_queued', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.bob_magicfolder)) + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.bob_magicfolder, u"file1", 3) + self._check_version_in_local_db(self.bob_magicfolder, u"file1", 3) + self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) + self._check_uploader_count('objects_succeeded', 1, magic=self.bob_magicfolder) + self._check_uploader_count('files_uploaded', 1, magic=self.bob_magicfolder) + self._check_uploader_count('objects_queued', 0, magic=self.bob_magicfolder) + self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder) + self._check_downloader_count('objects_conflicted', 0, magic=self.bob_magicfolder) - d.addCallback(lambda ign: self._check_version_in_dmd(self.alice_magicfolder, u"file1", 3)) - d.addCallback(lambda ign: self._check_version_in_local_db(self.alice_magicfolder, u"file1", 3)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 1, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) + self._check_version_in_dmd(self.alice_magicfolder, u"file1", 3) + self._check_version_in_local_db(self.alice_magicfolder, u"file1", 3) + self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_downloaded', 1, magic=self.alice_magicfolder) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + d.addCallback(check_state) def Alice_conflicts_with_Bobs_last_downloaded_uri(): if _debug: print "Alice conflicts with Bob\n" @@ -1454,15 +1465,18 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea d2.addCallback(lambda ign: downloaded_d) d2.addCallback(lambda ign: self.failUnless(alice_dmd.has_child(encoded_path_u))) return d2 - d.addCallback(lambda ign: Alice_conflicts_with_Bobs_last_downloaded_uri()) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 4, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 1, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 1, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 1, magic=self.bob_magicfolder)) + + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_downloader_count('objects_downloaded', 4, magic=self.bob_magicfolder) + self._check_downloader_count('objects_conflicted', 1, magic=self.bob_magicfolder) + self._check_downloader_count('objects_downloaded', 1, magic=self.alice_magicfolder) + self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + self._check_uploader_count('files_uploaded', 1, magic=self.bob_magicfolder) + self._check_uploader_count('objects_succeeded', 1, magic=self.bob_magicfolder) + d.addCallback(check_state) # prepare to perform another conflict test @inline_callbacks @@ -1473,11 +1487,15 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea self.bob_clock.advance(4) yield d d.addCallback(_wait_for, Alice_to_write_file2) - d.addCallback(lambda ign: self._check_version_in_dmd(self.alice_magicfolder, u"file2", 0)) - d.addCallback(lambda ign: self._check_version_in_local_db(self.alice_magicfolder, u"file2", 0)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 1, magic=self.bob_magicfolder)) + + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.alice_magicfolder, u"file2", 0) + self._check_version_in_local_db(self.alice_magicfolder, u"file2", 0) + self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + self._check_uploader_count('files_uploaded', 1, magic=self.bob_magicfolder) + d.addCallback(check_state) def advance(ign): alice_clock.advance(4) @@ -1504,34 +1522,41 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate(self.bob_magicfolder) if _debug: print "---- iterated bob's magicfolder" d.addCallback(lambda ign: _wait_for(None, Bob_to_rewrite_file2, alice=False)) - d.addCallback(lambda ign: self._check_version_in_dmd(self.bob_magicfolder, u"file2", 1)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 5, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 2, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 2, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_queued', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder)) + + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.bob_magicfolder, u"file2", 1) + self._check_downloader_count('objects_downloaded', 5, magic=self.bob_magicfolder) + self._check_downloader_count('objects_conflicted', 1, magic=self.bob_magicfolder) + self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) + self._check_uploader_count('objects_succeeded', 2, magic=self.bob_magicfolder) + self._check_uploader_count('files_uploaded', 2, magic=self.bob_magicfolder) + self._check_uploader_count('objects_queued', 0, magic=self.bob_magicfolder) + self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder) + d.addCallback(check_state) # XXX here we advance the clock and then test again to make sure no values are monotonically increasing # with each queue turn ;-p alice_clock.advance(6) bob_clock.advance(6) - d.addCallback(lambda ign: self._check_version_in_dmd(self.bob_magicfolder, u"file2", 1)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 5)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1)) - d.addCallback(lambda ign: self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 2, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 2, magic=self.bob_magicfolder)) -## d.addCallback(lambda ign: self._check_uploader_count('objects_queued', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 2, magic=self.bob_magicfolder)) + + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.bob_magicfolder, u"file2", 1) + self._check_downloader_count('objects_downloaded', 5) + self._check_downloader_count('objects_conflicted', 1) + self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) + self._check_uploader_count('objects_succeeded', 2, magic=self.bob_magicfolder) + self._check_uploader_count('files_uploaded', 2, magic=self.bob_magicfolder) + self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder) + self._check_uploader_count('files_uploaded', 2, magic=self.bob_magicfolder) + d.addCallback(check_state) def Alice_conflicts_with_Bobs_last_uploaded_uri(): if _debug: print "Alice conflicts with Bob\n" @@ -1549,17 +1574,20 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea d2.addCallback(lambda ign: self.failUnless(alice_dmd.has_child(encoded_path_u))) return d2 d.addCallback(lambda ign: Alice_conflicts_with_Bobs_last_uploaded_uri()) - d.addCallback(lambda ign: self._check_version_in_dmd(self.bob_magicfolder, u"file2", 5)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 6)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1)) - d.addCallback(lambda ign: self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 2, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 2, magic=self.bob_magicfolder)) -## d.addCallback(lambda ign: self._check_uploader_count('objects_queued', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder)) + + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.bob_magicfolder, u"file2", 5) + self._check_downloader_count('objects_downloaded', 6) + self._check_downloader_count('objects_conflicted', 1) + self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) + self._check_uploader_count('objects_succeeded', 2, magic=self.bob_magicfolder) + self._check_uploader_count('files_uploaded', 2, magic=self.bob_magicfolder) + self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder) + d.addCallback(check_state) def foo(ign): alice_clock.advance(6) @@ -1568,10 +1596,13 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea bob_clock.advance(6) d.addCallback(foo) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 6)) + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_conflicted', 1) + self._check_downloader_count('objects_downloaded', 6) + d.addCallback(check_state) # prepare to perform another conflict test @inline_callbacks @@ -1581,12 +1612,16 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield self.alice_fileops.write(self.file_path, "something") yield iterate(self.alice_magicfolder) d.addCallback(_wait_for, Alice_to_write_file3) - d.addCallback(lambda ign: self._check_version_in_dmd(self.alice_magicfolder, u"file3", 0)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 7)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) + + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.alice_magicfolder, u"file3", 0) + self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_downloaded', 7) + self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder) + self._check_downloader_count('objects_conflicted', 1) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + d.addCallback(check_state) @inline_callbacks def Bob_to_rewrite_file3(): @@ -1597,17 +1632,22 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield self.bob_fileops.write(self.file_path, "roger roger") yield iterate(self.bob_magicfolder) d.addCallback(lambda ign: _wait_for(None, Bob_to_rewrite_file3, alice=False)) - d.addCallback(lambda ign: self._check_version_in_dmd(self.bob_magicfolder, u"file3", 1)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 7)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1)) - d.addCallback(lambda ign: self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_succeeded', 3, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 3, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('objects_queued', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder)) - d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 3, magic=self.alice_magicfolder)) + + @log_call(action_type=u"check_state", include_args=[], include_result=False) + def check_state(ignored): + self._check_version_in_dmd(self.bob_magicfolder, u"file3", 1) + self._check_downloader_count('objects_downloaded', 7) + self._check_downloader_count('objects_conflicted', 1) + self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) + self._check_uploader_count('objects_succeeded', 3, magic=self.bob_magicfolder) + self._check_uploader_count('files_uploaded', 3, magic=self.bob_magicfolder) + self._check_uploader_count('objects_queued', 0, magic=self.bob_magicfolder) + self._check_uploader_count('directories_created', 0, magic=self.bob_magicfolder) + self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) + self._check_downloader_count('objects_downloaded', 3, magic=self.alice_magicfolder) + d.addCallback(check_state) + return d.addActionFinish() From 641cb8a5067c9bbbfa4b40a53a57436fd59c6eb9 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 28 Feb 2019 12:15:54 -0500 Subject: [PATCH 44/93] Make these checks a little more informative --- src/allmydata/test/test_magic_folder.py | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index e692355f6..cd39231ef 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -682,8 +682,17 @@ class CheckerMixin(object): def _check_version_in_dmd(self, magicfolder, relpath_u, expected_version): encoded_name_u = magicpath.path2magic(relpath_u) result = yield magicfolder.downloader._get_collective_latest_file(encoded_name_u) - self.assertTrue(result is not None) + self.assertIsNot( + result, + None, + "collective_latest_file({}) is None".format(encoded_name_u), + ) node, metadata = result + self.assertIsNot( + metadata, + None, + "collective_latest_file({}) metadata is None".format(encoded_name_u), + ) self.failUnlessEqual(metadata['version'], expected_version) def _check_version_in_local_db(self, magicfolder, relpath_u, expected_version): From ec5ebc273891534c3cc3917c85863f2c3ca0fdbf Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 28 Feb 2019 12:25:43 -0500 Subject: [PATCH 45/93] fix the Deferred interactions with that last Eliot change --- src/allmydata/test/test_magic_folder.py | 50 +++++++++++++++---------- 1 file changed, 30 insertions(+), 20 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index cd39231ef..328ab7392 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1320,9 +1320,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate(self.alice_magicfolder) d.addCallback(_wait_for, Alice_to_write_a_file) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.alice_magicfolder, u"file1", 0) + yield self._check_version_in_dmd(self.alice_magicfolder, u"file1", 0) self._check_version_in_local_db(self.alice_magicfolder, u"file1", 0) self._check_uploader_count('objects_failed', 0) self._check_uploader_count('objects_succeeded', 1) @@ -1358,9 +1359,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate(self.bob_magicfolder) d.addCallback(notify_bob_moved) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.alice_magicfolder, u"file1", 1) + yield self._check_version_in_dmd(self.alice_magicfolder, u"file1", 1) self._check_version_in_local_db(self.alice_magicfolder, u"file1", 1) self._check_uploader_count('objects_failed', 0) self._check_uploader_count('objects_succeeded', 2) @@ -1386,9 +1388,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea d.addCallback(_wait_for, Alice_to_rewrite_file) d.addCallback(lambda ign: iterate(self.bob_magicfolder)) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.alice_magicfolder, u"file1", 2) + yield self._check_version_in_dmd(self.alice_magicfolder, u"file1", 2) self._check_version_in_local_db(self.alice_magicfolder, u"file1", 2) self._check_uploader_count('objects_failed', 0) self._check_uploader_count('objects_succeeded', 3) @@ -1442,9 +1445,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate(self.bob_magicfolder) d.addCallback(lambda ign: _wait_for(None, Bob_to_rewrite_file, alice=False)) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.bob_magicfolder, u"file1", 3) + yield self._check_version_in_dmd(self.bob_magicfolder, u"file1", 3) self._check_version_in_local_db(self.bob_magicfolder, u"file1", 3) self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) self._check_uploader_count('objects_succeeded', 1, magic=self.bob_magicfolder) @@ -1497,9 +1501,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield d d.addCallback(_wait_for, Alice_to_write_file2) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.alice_magicfolder, u"file2", 0) + yield self._check_version_in_dmd(self.alice_magicfolder, u"file2", 0) self._check_version_in_local_db(self.alice_magicfolder, u"file2", 0) self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) self._check_downloader_count('objects_conflicted', 0, magic=self.alice_magicfolder) @@ -1532,9 +1537,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea if _debug: print "---- iterated bob's magicfolder" d.addCallback(lambda ign: _wait_for(None, Bob_to_rewrite_file2, alice=False)) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.bob_magicfolder, u"file2", 1) + yield self._check_version_in_dmd(self.bob_magicfolder, u"file2", 1) self._check_downloader_count('objects_downloaded', 5, magic=self.bob_magicfolder) self._check_downloader_count('objects_conflicted', 1, magic=self.bob_magicfolder) self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) @@ -1552,9 +1558,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea alice_clock.advance(6) bob_clock.advance(6) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.bob_magicfolder, u"file2", 1) + yield self._check_version_in_dmd(self.bob_magicfolder, u"file2", 1) self._check_downloader_count('objects_downloaded', 5) self._check_downloader_count('objects_conflicted', 1) self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) @@ -1584,9 +1591,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea return d2 d.addCallback(lambda ign: Alice_conflicts_with_Bobs_last_uploaded_uri()) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.bob_magicfolder, u"file2", 5) + yield self._check_version_in_dmd(self.bob_magicfolder, u"file2", 5) self._check_downloader_count('objects_downloaded', 6) self._check_downloader_count('objects_conflicted', 1) self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) @@ -1622,9 +1630,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate(self.alice_magicfolder) d.addCallback(_wait_for, Alice_to_write_file3) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.alice_magicfolder, u"file3", 0) + yield self._check_version_in_dmd(self.alice_magicfolder, u"file3", 0) self._check_downloader_count('objects_failed', 0, magic=self.alice_magicfolder) self._check_downloader_count('objects_downloaded', 7) self._check_downloader_count('objects_downloaded', 2, magic=self.alice_magicfolder) @@ -1642,9 +1651,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea yield iterate(self.bob_magicfolder) d.addCallback(lambda ign: _wait_for(None, Bob_to_rewrite_file3, alice=False)) - @log_call(action_type=u"check_state", include_args=[], include_result=False) + @log_call_deferred(action_type=u"check_state") + @inline_callbacks def check_state(ignored): - self._check_version_in_dmd(self.bob_magicfolder, u"file3", 1) + yield self._check_version_in_dmd(self.bob_magicfolder, u"file3", 1) self._check_downloader_count('objects_downloaded', 7) self._check_downloader_count('objects_conflicted', 1) self._check_uploader_count('objects_failed', 0, magic=self.bob_magicfolder) From ae59679875ced8b8b1067d0d8aa57a24004b04d0 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 28 Feb 2019 12:57:56 -0500 Subject: [PATCH 46/93] log this action --- src/allmydata/test/test_magic_folder.py | 1 + 1 file changed, 1 insertion(+) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 328ab7392..4ed5ed9e7 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1492,6 +1492,7 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea d.addCallback(check_state) # prepare to perform another conflict test + @log_call_deferred(action_type=u"alice:to-write:file2") @inline_callbacks def Alice_to_write_file2(): if _debug: print "Alice writes a file2\n" From 807568e09f26d1b111042de58c91362b2a2f447c Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 28 Feb 2019 20:57:09 -0500 Subject: [PATCH 47/93] Log downloads --- src/allmydata/frontends/magic_folder.py | 28 ++++++++++++++++++------- 1 file changed, 20 insertions(+), 8 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 7a24c2070..00cf23ba4 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1110,6 +1110,13 @@ PROCESS_ITEM = ActionType( u"A path which was found wanting of an update is receiving an update.", ) +DOWNLOAD_BEST_VERSION = ActionType( + u"magic-folder:download-best-version", + [], + [], + u"The content of a file in the Magic Folder is being downloaded.", +) + class Uploader(QueueMixin): def __init__(self, client, local_path_u, db, upload_dirnode, pending_delay, clock): @@ -1958,14 +1965,19 @@ class Downloader(QueueMixin, WriteFileMixin): if item.metadata.get('deleted', False): d.addCallback(lambda ign: self._rename_deleted_file(abspath_u)) else: - d.addCallback(lambda ign: item.file_node.download_best_version(progress=item.progress)) - d.addCallback( - lambda contents: self._write_downloaded_file( - self._local_path_u, abspath_u, contents, - is_conflict=is_conflict, - mtime=item.metadata.get('user_mtime', item.metadata.get('tahoe', {}).get('linkmotime')), - ) - ) + @eliotutil.inline_callbacks + def download_best_version(ignored): + with DOWNLOAD_BEST_VERSION(): + contents = yield item.file_node.download_best_version(progress=item.progress) + defer.returnValue( + self._write_downloaded_file( + self._local_path_u, abspath_u, contents, + is_conflict=is_conflict, + mtime=item.metadata.get('user_mtime', item.metadata.get('tahoe', {}).get('linkmotime')), + ) + ) + + d.addCallback(download_best_version) d.addCallback(do_update_db) d.addErrback(failed) From 29e3390fb965bf8056114aa86a4fb408224bf00c Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Fri, 1 Mar 2019 16:11:32 -0500 Subject: [PATCH 48/93] re-use log_call_deferred where it is easy to do so --- src/allmydata/frontends/magic_folder.py | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 00cf23ba4..d608fd1c5 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1965,17 +1965,15 @@ class Downloader(QueueMixin, WriteFileMixin): if item.metadata.get('deleted', False): d.addCallback(lambda ign: self._rename_deleted_file(abspath_u)) else: - @eliotutil.inline_callbacks + @eliotutil.log_call_deferred(DOWNLOAD_BEST_VERSION.action_type) def download_best_version(ignored): - with DOWNLOAD_BEST_VERSION(): - contents = yield item.file_node.download_best_version(progress=item.progress) - defer.returnValue( - self._write_downloaded_file( - self._local_path_u, abspath_u, contents, - is_conflict=is_conflict, - mtime=item.metadata.get('user_mtime', item.metadata.get('tahoe', {}).get('linkmotime')), - ) - ) + d = DeferredContext(item.file_node.download_best_version(progress=item.progress)) + d.addCallback(lambda contents: self._write_downloaded_file( + self._local_path_u, abspath_u, contents, + is_conflict=is_conflict, + mtime=item.metadata.get('user_mtime', item.metadata.get('tahoe', {}).get('linkmotime')), + )) + return d.result d.addCallback(download_best_version) From 1d0c862c54d2b4f4e188e546e8e3c46ca4a60514 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 4 Mar 2019 16:22:06 -0500 Subject: [PATCH 49/93] convert some tests over to the new base class in support of better logging --- src/allmydata/test/common.py | 7 +++++++ src/allmydata/test/eliotutil.py | 11 ++++++----- src/allmydata/test/test_inotify.py | 19 +++++++++++-------- src/allmydata/test/test_magic_folder.py | 4 +--- src/allmydata/util/eliotutil.py | 3 ++- 5 files changed, 27 insertions(+), 17 deletions(-) diff --git a/src/allmydata/test/common.py b/src/allmydata/test/common.py index 5d44dd0e5..06a7161ff 100644 --- a/src/allmydata/test/common.py +++ b/src/allmydata/test/common.py @@ -2,6 +2,10 @@ __all__ = [ "SyncTestCase", "AsyncTestCase", "AsyncBrokenTestCase", + + "flush_logged_errors", + "skip", + "skipIf", ] import os, random, struct @@ -16,11 +20,14 @@ from zope.interface import implementer from testtools import ( TestCase, + skip, + skipIf, ) from testtools.twistedsupport import ( SynchronousDeferredRunTest, AsynchronousDeferredRunTest, AsynchronousDeferredRunTestForBrokenTwisted, + flush_logged_errors, ) from twisted.internet import defer diff --git a/src/allmydata/test/eliotutil.py b/src/allmydata/test/eliotutil.py index 90ff9179c..09d34f938 100644 --- a/src/allmydata/test/eliotutil.py +++ b/src/allmydata/test/eliotutil.py @@ -57,22 +57,23 @@ def eliot_logged_test(f): @wraps(f) def run_and_republish(self, *a, **kw): + # Unfortunately the only way to get at the global/default logger... + # This import is delayed here so that we get the *current* default + # logger at the time the decorated function is run. + from eliot._output import _DEFAULT_LOGGER as default_logger + def republish(): # This is called as a cleanup function after capture_logging has # restored the global/default logger to its original state. We # can now emit messages that go to whatever global destinations # are installed. - # Unfortunately the only way to get at the global/default - # logger... - from eliot._output import _DEFAULT_LOGGER as logger - # storage.logger.serialize() seems like it would make more sense # than storage.logger.messages here. However, serialize() # explodes, seemingly as a result of double-serializing the logged # messages. I don't understand this. for msg in storage.logger.messages: - logger.write(msg) + default_logger.write(msg) # And now that we've re-published all of the test's messages, we # can finish the test's action. diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index ea8c90315..77ea97fa9 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -12,21 +12,22 @@ import sys from twisted.internet import defer, reactor from twisted.python import filepath, runtime -from twisted.trial import unittest from allmydata.frontends.magic_folder import get_inotify_module - +from .common import ( + AsyncTestCase, + skip, + skipIf, +) inotify = get_inotify_module() -class INotifyTests(unittest.TestCase): +@skipIf(runtime.platformType == "win32", "inotify does not yet work on windows") +class INotifyTests(AsyncTestCase): """ Define all the tests for the basic functionality exposed by L{inotify.INotify}. """ - if runtime.platformType == "win32": - skip = "inotify does not yet work on windows" - def setUp(self): self.ignore_count = 0 self.dirname = filepath.FilePath(self.mktemp()) @@ -34,6 +35,7 @@ class INotifyTests(unittest.TestCase): self.inotify = inotify.INotify() self.inotify.startReading() self.addCleanup(self.inotify.stopReading) + return super(INotifyTests, self).setUp() def _notificationTest(self, mask, operation, expectedPath=None, ignore_count=0): @@ -215,6 +217,7 @@ class INotifyTests(unittest.TestCase): set(['close_write', 'access', 'open'])) + @skip("not relevant") def test_recursiveWatch(self): """ L{inotify.INotify.watch} with recursive==True will add all the @@ -230,9 +233,9 @@ class INotifyTests(unittest.TestCase): self.inotify.watch(self.dirname, recursive=True) for d in dirs: self.assertTrue(self.inotify._isWatched(d)) - test_recursiveWatch.skip = "not relevant" + @skip("Based on Twisted implementation details; not relevant") def test_connectionLostError(self): """ L{inotify.INotify.connectionLost} if there's a problem while closing @@ -243,7 +246,7 @@ class INotifyTests(unittest.TestCase): os.close(in_._fd) in_.loseConnection() self.flushLoggedErrors() - test_connectionLostError.skip = "Based on Twisted implementation details; not relevant" + def test_noAutoAddSubdirectory(self): """ diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 4ed5ed9e7..d0e496a95 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -9,9 +9,6 @@ from twisted.internet import defer, task, reactor from twisted.python.runtime import platform from twisted.python.filepath import FilePath -from testtools import ( - skipIf, -) from testtools.matchers import ( Not, Is, @@ -41,6 +38,7 @@ from .common import ( ShouldFailMixin, SyncTestCase, AsyncTestCase, + skipIf, ) from .cli.test_magic_folder import MagicFolderCLITestMixin diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index 696a66afc..535f4913d 100644 --- a/src/allmydata/util/eliotutil.py +++ b/src/allmydata/util/eliotutil.py @@ -361,6 +361,7 @@ class _EliotLogging(Service): self.twisted_observer = _TwistedLoggerToEliotObserver() globalLogPublisher.addObserver(self.twisted_observer) add_destinations(*self.destinations) + return Service.startService(self) def stopService(self): @@ -368,7 +369,7 @@ class _EliotLogging(Service): remove_destination(dest) globalLogPublisher.removeObserver(self.twisted_observer) self.stdlib_cleanup() - + return Service.stopService(self) @implementer(ILogObserver) From 944cb6f4257bcd2c36c39e62d18ba4fb94a46c3d Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 4 Mar 2019 18:30:29 -0500 Subject: [PATCH 50/93] switch to testtools-compatible skips --- src/allmydata/test/test_inotify.py | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 77ea97fa9..c14669b64 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -116,6 +116,11 @@ class INotifyTests(AsyncTestCase): return self._notificationTest(inotify.IN_CLOSE_WRITE, operation) + # The watchdog implementation makes it difficult to get this event. Also, + # the magic-folder implementation doesn't really *need* exactly this + # event. It would be nice to get some event on move, which watchdog gives + # us. But this test is overly specific for our purposes. + @skip("not available on watchdog") def test_movedFrom(self): """ Moving a file out of a monitored directory sends an @@ -126,13 +131,10 @@ class INotifyTests(AsyncTestCase): path.moveTo(filepath.FilePath(self.mktemp())) return self._notificationTest(inotify.IN_MOVED_FROM, operation) - # The watchdog implementation makes it difficult to get this event. Also, - # the magic-folder implementation doesn't really *need* exactly this - # event. It would be nice to get some event on move, which watchdog gives - # us. But this test is overly specific for our purposes. - test_movedFrom.skip = "not available on watchdog" + # Ditto the comment on test_movedFrom about watchdog here. + @skip("not available on watchdog") def test_movedTo(self): """ Moving a file into a monitored directory sends an @@ -144,8 +146,6 @@ class INotifyTests(AsyncTestCase): p.moveTo(path) return self._notificationTest(inotify.IN_MOVED_TO, operation) - # Ditto the comment on test_movedFrom about watchdog here. - test_movedTo.skip = "not available on watchdog" def test_delete(self): @@ -274,6 +274,7 @@ class INotifyTests(AsyncTestCase): return d + @skip("Not gonna implement autoAdd") def test_complexSubdirectoryAutoAdd(self): """ L{inotify.INotify} with autoAdd==True for a watched path @@ -319,4 +320,3 @@ class INotifyTests(AsyncTestCase): filename.setContent( filename.path.encode(sys.getfilesystemencoding())) return d - test_complexSubdirectoryAutoAdd.skip = "Not gonna implement autoAdd" From 8bec797f665b1b975150d6b8d5db1b6cd84c4b8c Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 4 Mar 2019 18:52:25 -0500 Subject: [PATCH 51/93] somewhat better failure messages --- src/allmydata/test/test_inotify.py | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index c14669b64..030fda647 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -183,7 +183,10 @@ class INotifyTests(AsyncTestCase): # delay our check of that watch state a bit. def _(): try: - self.assertFalse(self.inotify._isWatched(subdir)) + self.assertFalse( + self.inotify._isWatched(subdir), + "{} not un-watched. watches = {}".format(subdir, self.inotify._watches), + ) d.callback(None) except Exception: d.errback() @@ -196,7 +199,10 @@ class INotifyTests(AsyncTestCase): callbacks=[_callback], recursive=True, ) - self.assertTrue(self.inotify._isWatched(subdir)) + self.assertTrue( + self.inotify._isWatched(subdir), + "{} not watched. watches = {}".format(subdir, self.inotify._watches), + ) subdir.remove() return d From b52524f70197e6590aba8e659725ce19719c393e Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 4 Mar 2019 19:58:23 -0500 Subject: [PATCH 52/93] this test probably makes no sense for watchdog --- src/allmydata/test/test_inotify.py | 1 + 1 file changed, 1 insertion(+) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 030fda647..e66ebe887 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -168,6 +168,7 @@ class INotifyTests(AsyncTestCase): return notified + @skipIf("watchdog is differently recursive") def test_simpleDeleteDirectory(self): """ L{inotify.INotify} removes a directory from the watchlist when From bfa93adad0d68651beb4816312dfac24032e097a Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 4 Mar 2019 19:58:48 -0500 Subject: [PATCH 53/93] expose another implementation detail! --- src/allmydata/watchdog/inotify.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index eaa74c95f..b14159af4 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -16,7 +16,7 @@ __all__ = [ "IN_CLOSE_WRITE", "IN_OPEN", "IN_MOVED_FROM", "IN_MOVED_TO", "IN_CREATE", "IN_DELETE", "IN_DELETE_SELF", "IN_MOVE_SELF", "IN_UNMOUNT", "IN_ONESHOT", "IN_Q_OVERFLOW", "IN_IGNORED", "IN_ONLYDIR", "IN_DONT_FOLLOW", "IN_MOVED", - "IN_MASK_ADD", "IN_ISDIR", "IN_CLOSE", "IN_CHANGED", + "IN_MASK_ADD", "IN_ISDIR", "IN_CLOSE", "IN_CHANGED", "_FLAG_TO_HUMAN", ] from watchdog.observers import Observer @@ -45,7 +45,8 @@ from allmydata.util.fake_inotify import humanReadableMask, \ IN_WATCH_MASK, IN_ACCESS, IN_MODIFY, IN_ATTRIB, IN_CLOSE_NOWRITE, IN_CLOSE_WRITE, \ IN_OPEN, IN_MOVED_FROM, IN_MOVED_TO, IN_CREATE, IN_DELETE, IN_DELETE_SELF, \ IN_MOVE_SELF, IN_UNMOUNT, IN_Q_OVERFLOW, IN_IGNORED, IN_ONLYDIR, IN_DONT_FOLLOW, \ - IN_MASK_ADD, IN_ISDIR, IN_ONESHOT, IN_CLOSE, IN_MOVED, IN_CHANGED + IN_MASK_ADD, IN_ISDIR, IN_ONESHOT, IN_CLOSE, IN_MOVED, IN_CHANGED, \ + _FLAG_TO_HUMAN from ..util.eliotutil import ( INOTIFY_EVENTS, From 4fc99b1b4df87ca315b6edb3a95d3f4c706c475d Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 4 Mar 2019 20:00:48 -0500 Subject: [PATCH 54/93] oops --- src/allmydata/test/test_inotify.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index e66ebe887..2b891f1f0 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -168,7 +168,7 @@ class INotifyTests(AsyncTestCase): return notified - @skipIf("watchdog is differently recursive") + @skip("watchdog is differently recursive") def test_simpleDeleteDirectory(self): """ L{inotify.INotify} removes a directory from the watchlist when From d4752bde1a88232684f9f3ec326116e761816a81 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 5 Mar 2019 18:50:17 -0500 Subject: [PATCH 55/93] try to get more precise watchdog event info --- src/allmydata/watchdog/inotify.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index b14159af4..5db35d9dd 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -73,7 +73,7 @@ MAYBE_NOTIFY = ActionType( _EVENT = Field( u"event", - lambda e: e.event_type, + lambda e: e.__class__.__name__, u"The watchdog event that has taken place.", validateInstanceOf(FileSystemEvent), ) From de9c681fe29a1a413c4e7a82e8e33fa4a3e0e7d7 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Fri, 15 Feb 2019 15:51:49 -0500 Subject: [PATCH 56/93] Let me query for direct children of a directory --- src/allmydata/magicfolderdb.py | 45 +++++++++++++++++++++++ src/allmydata/test/test_magic_folder.py | 47 +++++++++++++++++++++++++ 2 files changed, 92 insertions(+) diff --git a/src/allmydata/magicfolderdb.py b/src/allmydata/magicfolderdb.py index b74edc9da..043b7a915 100644 --- a/src/allmydata/magicfolderdb.py +++ b/src/allmydata/magicfolderdb.py @@ -88,6 +88,15 @@ def get_magicfolderdb(dbfile, stderr=sys.stderr, print >>stderr, e return None +class LocalPath(object): + @classmethod + def fromrow(self, row): + p = LocalPath() + p.relpath_u = row[0] + p.entry = PathEntry(*row[1:]) + return p + + class MagicFolderDB(object): VERSION = 1 @@ -121,6 +130,42 @@ class MagicFolderDB(object): last_downloaded_uri=last_downloaded_uri, last_downloaded_timestamp=last_downloaded_timestamp) + def get_direct_children(self, relpath_u): + """ + Given the relative path to a directory, return ``LocalPath`` instances + representing all direct children of that directory. + """ + # It would be great to not be interpolating data into query + # statements. However, query parameters are not supported in the + # position where we need them. + sqlitesafe_relpath_u = relpath_u.replace(u"'", u"''") + statement = ( + """ + SELECT + path, size, mtime_ns, ctime_ns, version, last_uploaded_uri, + last_downloaded_uri, last_downloaded_timestamp + FROM + local_files + WHERE + -- The "_" used here ensures there is at least one character + -- after the /. This prevents matching the path itself. + path LIKE '{path}/_%' AND + + -- The "_" used here serves a similar purpose. This allows + -- matching directory children but avoids matching their + -- children. + path NOT LIKE '{path}/_%/_%' + """ + ).format(path=sqlitesafe_relpath_u) + + self.cursor.execute(statement) + rows = self.cursor.fetchall() + return list( + LocalPath.fromrow(row) + for row + in rows + ) + def get_all_relpaths(self): """ Retrieve a set of all relpaths of files that have had an entry in magic folder db diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index d0e496a95..97659180c 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -534,6 +534,53 @@ class MagicFolderDbTests(SyncTestCase): self.assertTrue(entry is not None) self.assertEqual(entry.last_downloaded_uri, content_uri) + def test_get_direct_children(self): + """ + ``get_direct_children`` returns a list of ``PathEntry`` representing each + local file in the database which is a direct child of the given path. + """ + def add_file(relpath_u): + self.db.did_upload_version( + relpath_u=relpath_u, + version=0, + last_uploaded_uri=None, + last_downloaded_uri=None, + last_downloaded_timestamp=1234, + pathinfo=get_pathinfo(self.temp), + ) + paths = [ + u"some_random_file", + u"the_target_directory_is_elsewhere", + u"the_target_directory_is_not_this/", + u"the_target_directory_is_not_this/and_not_in_here", + u"the_target_directory/", + u"the_target_directory/foo", + u"the_target_directory/bar", + u"the_target_directory/baz", + u"the_target_directory/quux/", + u"the_target_directory/quux/exclude_grandchildren", + u"the_target_directory/quux/and_great_grandchildren/", + u"the_target_directory/quux/and_great_grandchildren/foo", + u"the_target_directory_is_over/stuff", + u"please_ignore_this_for_sure", + ] + for relpath_u in paths: + add_file(relpath_u) + + expected_paths = [ + u"the_target_directory/foo", + u"the_target_directory/bar", + u"the_target_directory/baz", + u"the_target_directory/quux/", + ] + + actual_paths = list( + localpath.relpath_u + for localpath + in self.db.get_direct_children(u"the_target_directory") + ) + self.assertEqual(expected_paths, actual_paths) + def iterate_downloader(magic): return magic.downloader._processing_iteration() From 70ec8f2963a48e8785475fa0c3a4d9da6367a441 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 07:51:55 -0500 Subject: [PATCH 57/93] log this case --- src/allmydata/frontends/magic_folder.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index d608fd1c5..54d330422 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -546,6 +546,12 @@ NOTIFIED_OBJECT_DISAPPEARED = MessageType( u"A path which generated a notification was not found on the filesystem. This is normal.", ) +NO_DATABASE_ENTRY = MessageType( + u"magic-folder:no-database-entry", + [], + u"There is no local database entry for a particular relative path in the magic folder.", +) + NOT_UPLOADING = MessageType( u"magic-folder:not-uploading", [], @@ -1335,6 +1341,7 @@ class Uploader(QueueMixin): db_entry = self._db.get_db_entry(relpath_u) if db_entry is None: + NO_DATABASE_ENTRY.log() return False last_downloaded_timestamp = now # is this correct? From da0bbd6bbaee90d96de3fd19b3b311685a788a48 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 07:58:47 -0500 Subject: [PATCH 58/93] Make this log message less confusing. The method name still needs to be fixed. --- src/allmydata/magicfolderdb.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/allmydata/magicfolderdb.py b/src/allmydata/magicfolderdb.py index 043b7a915..171dbe4e6 100644 --- a/src/allmydata/magicfolderdb.py +++ b/src/allmydata/magicfolderdb.py @@ -43,11 +43,11 @@ _INSERT_OR_UPDATE = Field.for_types( validateSetMembership({u"insert", u"update"}), ) -DID_UPLOAD_VERSION = ActionType( - u"magic-folder-db:did-upload-version", +UPDATE_ENTRY = ActionType( + u"magic-folder-db:update-entry", [RELPATH, VERSION, LAST_UPLOADED_URI, LAST_DOWNLOADED_URI, LAST_DOWNLOADED_TIMESTAMP, PATHINFO], [_INSERT_OR_UPDATE], - u"An file upload is being recorded in the database.", + u"Record some metadata about a relative path in the magic-folder.", ) @@ -176,7 +176,7 @@ class MagicFolderDB(object): return set([r[0] for r in rows]) def did_upload_version(self, relpath_u, version, last_uploaded_uri, last_downloaded_uri, last_downloaded_timestamp, pathinfo): - action = DID_UPLOAD_VERSION( + action = UPDATE_ENTRY( relpath=relpath_u, version=version, last_uploaded_uri=last_uploaded_uri, From 17540c78f3aa6d01541a07455db4f267a8fbf816 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 08:29:07 -0500 Subject: [PATCH 59/93] not going to get processed any other way on fsevents --- src/allmydata/frontends/magic_folder.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 54d330422..11248c669 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -546,6 +546,13 @@ NOTIFIED_OBJECT_DISAPPEARED = MessageType( u"A path which generated a notification was not found on the filesystem. This is normal.", ) +PROPAGATE_DIRECTORY_DELETION = ActionType( + u"magic-folder:propagate-directory-deletion", + [], + [], + u"Children of a deleted directory are being queued for upload processing.", +) + NO_DATABASE_ENTRY = MessageType( u"magic-folder:no-database-entry", [], @@ -1339,6 +1346,10 @@ class Uploader(QueueMixin): NOTIFIED_OBJECT_DISAPPEARED.log(path=fp) self._count('objects_disappeared') + with PROPAGATE_DIRECTORY_DELETION(): + for localpath in self._db.get_direct_children(relpath_u): + self._add_pending(localpath.relpath_u) + db_entry = self._db.get_db_entry(relpath_u) if db_entry is None: NO_DATABASE_ENTRY.log() From 600f263a3b82a08b0578cc04d4f9fda6efbfdc72 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 09:09:40 -0500 Subject: [PATCH 60/93] marginally improve reporting of uploader count failures --- src/allmydata/test/test_magic_folder.py | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 97659180c..4d751281c 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -751,8 +751,17 @@ class CheckerMixin(object): self.assertTrue(not os.path.exists(path)) def _check_uploader_count(self, name, expected, magic=None): - self.failUnlessReallyEqual(self._get_count('uploader.'+name, client=(magic or self.alice_magicfolder)._client), - expected) + if magic is None: + magic = self.alice_magicfolder + self.failUnlessReallyEqual( + self._get_count( + 'uploader.'+name, + client=magic._client, + ), + expected, + "Pending: {}\n" + "Deque: {}\n".format(magic.uploader._pending, magic.uploader._deque), + ) def _check_downloader_count(self, name, expected, magic=None): self.failUnlessReallyEqual(self._get_count('downloader.'+name, client=(magic or self.bob_magicfolder)._client), From cf2105364f884031fe47c9820ee957177aca8715 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 10:34:13 -0500 Subject: [PATCH 61/93] Try to fix another race in this test --- src/allmydata/test/test_magic_folder.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 4d751281c..ca54cb6ef 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1683,6 +1683,8 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea self.file_path = abspath_expanduser_unicode(u"file3", base=self.alice_magicfolder.uploader._local_path_u) yield self.alice_fileops.write(self.file_path, "something") yield iterate(self.alice_magicfolder) + # Make sure Bob gets the file before we do anything else. + yield iterate(self.bob_magicfolder) d.addCallback(_wait_for, Alice_to_write_file3) @log_call_deferred(action_type=u"check_state") From edfd9d3f928a44126db86f7e5adfcdad5edf96af Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 12:19:52 -0500 Subject: [PATCH 62/93] rejected --- src/allmydata/test/test_magic_folder.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index ca54cb6ef..e8bb108a3 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -612,8 +612,6 @@ class FileOperationsHelper(object): propagate. For the mock tests this is easy, since we're sending them sychronously. For the Real tests we have to wait for the actual inotify thing. - - We could write this as a mixin instead; might fit existing style better? """ _timeout = 5.0 From 831836d5f6d8b77f78a93449a0901eaa8951f8c4 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 13:44:19 -0500 Subject: [PATCH 63/93] don't try to propagate for non-directories --- src/allmydata/frontends/magic_folder.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 11248c669..bfafc964d 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1346,9 +1346,10 @@ class Uploader(QueueMixin): NOTIFIED_OBJECT_DISAPPEARED.log(path=fp) self._count('objects_disappeared') - with PROPAGATE_DIRECTORY_DELETION(): - for localpath in self._db.get_direct_children(relpath_u): - self._add_pending(localpath.relpath_u) + if pathinfo.isdir: + with PROPAGATE_DIRECTORY_DELETION(): + for localpath in self._db.get_direct_children(relpath_u): + self._add_pending(localpath.relpath_u) db_entry = self._db.get_db_entry(relpath_u) if db_entry is None: From 7440ff6b933cc368db62431ca26c656163157425 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 14:46:06 -0500 Subject: [PATCH 64/93] log collective scanning --- src/allmydata/frontends/magic_folder.py | 21 ++++++++++++++++++--- 1 file changed, 18 insertions(+), 3 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index bfafc964d..d4d89383e 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1732,12 +1732,21 @@ class Downloader(QueueMixin, WriteFileMixin): file node and metadata for the latest version of the file located in the magic-folder collective directory. """ - collective_dirmap_d = self._collective_dirnode.list() + action = start_action( + action_type=u"magic-folder:downloader:get-latest-file", + name=filename, + ) + with action.context(): + collective_dirmap_d = DeferredContext(self._collective_dirnode.list()) def scan_collective(result): + Message.log( + message_type=u"magic-folder:downloader:get-latest-file:collective-scan", + dmds=result.keys(), + ) list_of_deferreds = [] for dir_name in result.keys(): # XXX make sure it's a directory - d = defer.succeed(None) + d = DeferredContext(defer.succeed(None)) d.addCallback(lambda x, dir_name=dir_name: result[dir_name][0].get_child_and_metadata(filename)) list_of_deferreds.append(d) deferList = defer.DeferredList(list_of_deferreds, consumeErrors=True) @@ -1749,12 +1758,18 @@ class Downloader(QueueMixin, WriteFileMixin): node = None for success, result in deferredList: if success: + Message.log( + message_type=u"magic-folder:downloader:get-latest-file:version", + version=result[1]['version'], + ) if node is None or result[1]['version'] > max_version: node, metadata = result max_version = result[1]['version'] + else: + write_traceback() return node, metadata collective_dirmap_d.addCallback(highest_version) - return collective_dirmap_d + return collective_dirmap_d.addActionFinish() def _scan_remote_dmd(self, nickname, dirnode, scan_batch): with SCAN_REMOTE_DMD(nickname=nickname).context(): From 3ab713859815b81700948ddd5d7f1ea4bb3c1309 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 15:02:28 -0500 Subject: [PATCH 65/93] some imports we need --- src/allmydata/frontends/magic_folder.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index d4d89383e..1e49616b0 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -19,6 +19,8 @@ from zope.interface import Interface, Attribute, implementer from eliot import ( Field, + Message, + start_action, ActionType, MessageType, write_failure, From 81ca822edf744efeffcd800abfb3175c4e8e541a Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 15:13:59 -0500 Subject: [PATCH 66/93] Cut the cost of this logging when logging is disabled --- src/allmydata/frontends/magic_folder.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 1e49616b0..deabb2a50 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -522,10 +522,11 @@ MAYBE_UPLOAD = MessageType( u"A decision is being made about whether to upload a file.", ) -PENDING = Field.for_types( +PENDING = Field( u"pending", - [list], + lambda s: list(s), u"The paths which are pending processing.", + eliotutil.validateInstanceOf(set), ) REMOVE_FROM_PENDING = ActionType( @@ -1337,7 +1338,7 @@ class Uploader(QueueMixin): pathinfo = get_pathinfo(unicode_from_filepath(fp)) try: - with REMOVE_FROM_PENDING(relpath=relpath_u, pending=list(self._pending)): + with REMOVE_FROM_PENDING(relpath=relpath_u, pending=self._pending): self._pending.remove(relpath_u) except KeyError: pass From db7af2661a8a40f819e666cf7dcd62e4087529d2 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 15:14:13 -0500 Subject: [PATCH 67/93] Close a window for a race condition in notification processing --- src/allmydata/frontends/magic_folder.py | 18 +++++++++++++++--- 1 file changed, 15 insertions(+), 3 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index deabb2a50..5524c485a 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1334,14 +1334,26 @@ class Uploader(QueueMixin): MAYBE_UPLOAD.log(relpath=relpath_u) if now is None: now = time.time() - fp = self._get_filepath(relpath_u) - pathinfo = get_pathinfo(unicode_from_filepath(fp)) - try: + # Take this item out of the pending set before we do any + # I/O-based processing related to it. If a further change + # takes place after we remove it from this set, we want it to + # end up in the set again. If we haven't gotten around to + # doing the I/O-based processing yet then the worst that will + # happen is we'll do a little redundant processing. + # + # If we did it the other way around, the sequence of events + # might be something like: we do some I/O, someone else does + # some I/O, a notification gets discarded because the path is + # still in the pending set, _then_ we remove it from the + # pending set. In such a circumstance, we've missed some I/O + # that we should have responded to. with REMOVE_FROM_PENDING(relpath=relpath_u, pending=self._pending): self._pending.remove(relpath_u) except KeyError: pass + fp = self._get_filepath(relpath_u) + pathinfo = get_pathinfo(unicode_from_filepath(fp)) encoded_path_u = magicpath.path2magic(relpath_u) if not pathinfo.exists: From f2cfad0cb9b1693258474fa2081e1e8d8f924175 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 15:14:50 -0500 Subject: [PATCH 68/93] There _is_ no traceback. It's an else. --- src/allmydata/frontends/magic_folder.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 5524c485a..3e0b14d36 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1781,7 +1781,9 @@ class Downloader(QueueMixin, WriteFileMixin): node, metadata = result max_version = result[1]['version'] else: - write_traceback() + Message.log( + message_type="magic-folder:downlodaer:get-latest-file:failed", + ) return node, metadata collective_dirmap_d.addCallback(highest_version) return collective_dirmap_d.addActionFinish() From ed755cf59052e8f4da2d7ccc3ae2de2df078e9af Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 16:01:51 -0500 Subject: [PATCH 69/93] it didn't start if the path is invalid --- src/allmydata/frontends/magic_folder.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 3e0b14d36..6dee99af5 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1321,11 +1321,11 @@ class Uploader(QueueMixin): d = DeferredContext(defer.succeed(False)) relpath_u = item.relpath_u - item.set_status('started', self._clock.seconds()) if relpath_u is None: item.set_status('invalid_path', self._clock.seconds()) return d.addActionFinish() + item.set_status('started', self._clock.seconds()) precondition(isinstance(relpath_u, unicode), relpath_u) precondition(not relpath_u.endswith(u'/'), relpath_u) From 4b0b269b56df7d2efb2b36c22c42a49a750562af Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 16:02:20 -0500 Subject: [PATCH 70/93] Perform the asserts earlier --- src/allmydata/frontends/magic_folder.py | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 6dee99af5..5da32ecef 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1318,17 +1318,16 @@ class Uploader(QueueMixin): """ # Uploader with PROCESS_ITEM(item=item).context(): - d = DeferredContext(defer.succeed(False)) - relpath_u = item.relpath_u + precondition(isinstance(relpath_u, unicode), relpath_u) + precondition(not relpath_u.endswith(u'/'), relpath_u) + d = DeferredContext(defer.succeed(False)) if relpath_u is None: item.set_status('invalid_path', self._clock.seconds()) return d.addActionFinish() item.set_status('started', self._clock.seconds()) - precondition(isinstance(relpath_u, unicode), relpath_u) - precondition(not relpath_u.endswith(u'/'), relpath_u) def _maybe_upload(ign, now=None): MAYBE_UPLOAD.log(relpath=relpath_u) From c2e19cc098224c93720c486ee0c0748734891dff Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 16:34:34 -0500 Subject: [PATCH 71/93] fix a raft of directory handling issues --- src/allmydata/frontends/magic_folder.py | 67 +++++++++++++++++-------- 1 file changed, 46 insertions(+), 21 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 5da32ecef..b0577a611 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1321,6 +1321,7 @@ class Uploader(QueueMixin): relpath_u = item.relpath_u precondition(isinstance(relpath_u, unicode), relpath_u) precondition(not relpath_u.endswith(u'/'), relpath_u) + encoded_path_u = magicpath.path2magic(relpath_u) d = DeferredContext(defer.succeed(False)) if relpath_u is None: @@ -1328,11 +1329,6 @@ class Uploader(QueueMixin): return d.addActionFinish() item.set_status('started', self._clock.seconds()) - - def _maybe_upload(ign, now=None): - MAYBE_UPLOAD.log(relpath=relpath_u) - if now is None: - now = time.time() try: # Take this item out of the pending set before we do any # I/O-based processing related to it. If a further change @@ -1351,25 +1347,41 @@ class Uploader(QueueMixin): self._pending.remove(relpath_u) except KeyError: pass + fp = self._get_filepath(relpath_u) pathinfo = get_pathinfo(unicode_from_filepath(fp)) - encoded_path_u = magicpath.path2magic(relpath_u) + + db_entry_is_dir = False + db_entry = self._db.get_db_entry(relpath_u) + if db_entry is None: + # Maybe it was a directory! + db_entry = self._db.get_db_entry(relpath_u + u"/") + if db_entry is None: + NO_DATABASE_ENTRY.log() + else: + db_entry_is_dir = True + + def _maybe_upload(ign, now=None): + MAYBE_UPLOAD.log(relpath=relpath_u) + if now is None: + now = time.time() if not pathinfo.exists: # FIXME merge this with the 'isfile' case. NOTIFIED_OBJECT_DISAPPEARED.log(path=fp) self._count('objects_disappeared') - if pathinfo.isdir: - with PROPAGATE_DIRECTORY_DELETION(): - for localpath in self._db.get_direct_children(relpath_u): - self._add_pending(localpath.relpath_u) - - db_entry = self._db.get_db_entry(relpath_u) if db_entry is None: - NO_DATABASE_ENTRY.log() + # If it exists neither on the filesystem nor in the + # database, it's neither a creation nor a deletion and + # there's nothing more to do. return False + # if pathinfo.isdir: + # with PROPAGATE_DIRECTORY_DELETION(): + # for localpath in self._db.get_direct_children(relpath_u): + # self._add_pending(localpath.relpath_u) + last_downloaded_timestamp = now # is this correct? if is_new_file(pathinfo, db_entry): @@ -1413,9 +1425,17 @@ class Uploader(QueueMixin): if db_entry.last_uploaded_uri is not None: metadata['last_uploaded_uri'] = db_entry.last_uploaded_uri + if db_entry_is_dir: + real_encoded_path_u = encoded_path_u + magicpath.path2magic(u"/") + real_relpath_u = relpath_u + u"/" + else: + real_encoded_path_u = encoded_path_u + real_relpath_u = relpath_u + empty_uploadable = Data("", self._client.convergence) d2 = DeferredContext(self._upload_dirnode.add_file( - encoded_path_u, empty_uploadable, + real_encoded_path_u, + empty_uploadable, metadata=metadata, overwrite=True, progress=item.progress, @@ -1428,7 +1448,7 @@ class Uploader(QueueMixin): # immediately re-download it when we start up next last_downloaded_uri = metadata.get('last_downloaded_uri', filecap) self._db.did_upload_version( - relpath_u, + real_relpath_u, new_version, filecap, last_downloaded_uri, @@ -1446,31 +1466,36 @@ class Uploader(QueueMixin): if not getattr(self._notifier, 'recursive_includes_new_subdirectories', False): self._notifier.watch(fp, mask=self.mask, callbacks=[self._notify], recursive=True) - db_entry = self._db.get_db_entry(relpath_u) DIRECTORY_PATHENTRY.log(pathentry=db_entry) if not is_new_file(pathinfo, db_entry): NOT_NEW_DIRECTORY.log() return False uploadable = Data("", self._client.convergence) - encoded_path_u += magicpath.path2magic(u"/") with PROCESS_DIRECTORY().context() as action: upload_d = DeferredContext(self._upload_dirnode.add_file( - encoded_path_u, uploadable, + encoded_path_u + magicpath.path2magic(u"/"), + uploadable, metadata={"version": 0}, overwrite=True, progress=item.progress, )) - def _dir_succeeded(ign): + def _dir_succeeded(dirnode): action.add_success_fields(created_directory=relpath_u) self._count('directories_created') + self._db.did_upload_version( + relpath_u + u"/", + version=0, + last_uploaded_uri=dirnode.get_uri(), + last_downloaded_uri=None, + last_downloaded_timestamp=now, + pathinfo=pathinfo, + ) upload_d.addCallback(_dir_succeeded) upload_d.addCallback(lambda ign: self._scan(relpath_u)) upload_d.addCallback(lambda ign: True) return upload_d.addActionFinish() elif pathinfo.isfile: - db_entry = self._db.get_db_entry(relpath_u) - last_downloaded_timestamp = now if db_entry is None: From 0822a711634b655b23b04b81b819044242f01070 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 16:54:37 -0500 Subject: [PATCH 72/93] If it's some _other_ error then propagate it! --- src/allmydata/test/test_magic_folder.py | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index e8bb108a3..d72f50503 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -3,7 +3,7 @@ import os, sys, time import stat, shutil, json import mock from os.path import join, exists, isdir -from errno import ENOENT +from errno import ENOENT, EISDIR from twisted.internet import defer, task, reactor from twisted.python.runtime import platform @@ -659,7 +659,13 @@ class FileOperationsHelper(object): def delete(self, path_u): fname = path_u d = self._uploader.set_hook('inotify') - os.unlink(fname) + try: + os.unlink(fname) + except OSError as e: + if e.errno == EISDIR: + os.rmdir(fname) + else: + raise self._maybe_notify(fname, self._inotify.IN_DELETE) return d.addTimeout(self._timeout, reactor) From 515475022ab6a7f7e9b453ce87094341ef1e6162 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 11 Mar 2019 08:44:58 -0400 Subject: [PATCH 73/93] add a test for deleting a file and its containing directory at about the same time --- src/allmydata/test/test_magic_folder.py | 43 +++++++++++++++++++++++++ 1 file changed, 43 insertions(+) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index d72f50503..de49b406f 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -2199,6 +2199,49 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall self.assertThat(metadata['version'], Equals(1)) self.assertThat(metadata['deleted'], Equals(True)) + def test_delete_sub_directory_containing_file(self): + reldir_u = u'subdir' + relpath_u = os.path.join(reldir_u, u'some-file') + content = u'some great content' + yield self._create_directory_with_file( + relpath_u, + content, + ) + # Delete the sub-directory and the file in it. Don't wait in between + # because the case where all events are delivered before any + # processing happens is interesting. And don't use the fileops API to + # delete the contained file so that we don't necessarily generate a + # notification for that path at all. We require that the + # implementation behave correctly when receiving only the notification + # for the containing directory. + os.unlink(os.path.join(self.local_dir, relpath_u)) + yield self.fileops.delete(os.path.join(self.local_dir, reldir_u)) + + # Now allow processing. + yield iterate(self.magicfolder) + # Give it some extra time because of recursive directory processing. + yield iterate(self.magicfolder) + + # Deletion of both entities should have been uploaded. + downloader = self.magicfolder.downloader + encoded_dir_u = magicpath.path2magic(reldir_u + u"/") + encoded_path_u = magicpath.path2magic(relpath_u) + + dir_node, dir_meta = yield downloader._get_collective_latest_file(encoded_dir_u) + path_node, path_meta = yield downloader._get_collective_latest_file(encoded_path_u) + + self.expectThat(dir_node, Not(Is(None)), "dir node") + self.expectThat(dir_meta, ContainsDict({ + "version": Equals(1), + "deleted": Equals(True), + }), "dir meta") + + self.expectThat(path_node, Not(Is(None)), "path node") + self.expectThat(path_meta, ContainsDict({ + "version": Equals(1), + "deleted": Equals(True), + }), "path meta") + @skipIf(support_missing, support_message) class MockTestAliceBob(MagicFolderAliceBobTestMixin, AsyncTestCase): From c5c7f954e91a1e7862924a0c979155286f838141 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 16:57:15 -0500 Subject: [PATCH 74/93] fix it! --- src/allmydata/frontends/magic_folder.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index b0577a611..4a5dc8a15 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1377,10 +1377,10 @@ class Uploader(QueueMixin): # there's nothing more to do. return False - # if pathinfo.isdir: - # with PROPAGATE_DIRECTORY_DELETION(): - # for localpath in self._db.get_direct_children(relpath_u): - # self._add_pending(localpath.relpath_u) + if pathinfo.isdir or db_entry_is_dir: + with PROPAGATE_DIRECTORY_DELETION(): + for localpath in self._db.get_direct_children(relpath_u): + self._add_pending(localpath.relpath_u) last_downloaded_timestamp = now # is this correct? From 4cccf5a316b8e99cf2f9e06c8ce515e84246303e Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 20:16:51 -0500 Subject: [PATCH 75/93] it sure would be useful to be able to inspect these --- src/allmydata/test/test_magic_folder.py | 1 - 1 file changed, 1 deletion(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index de49b406f..cddc04c7b 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -1773,7 +1773,6 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall def tearDown(self): d = DeferredContext(super(SingleMagicFolderTestMixin, self).tearDown()) d.addCallback(self.cleanup) - shutil.rmtree(self.basedir, ignore_errors=True) return d.result def _createdb(self): From e0b7919ad8c3dffc5648a523f2f53b86289dc5a1 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Wed, 6 Mar 2019 20:27:36 -0500 Subject: [PATCH 76/93] macOS is picky --- src/allmydata/test/test_magic_folder.py | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index cddc04c7b..7fb0d3c66 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -659,13 +659,11 @@ class FileOperationsHelper(object): def delete(self, path_u): fname = path_u d = self._uploader.set_hook('inotify') - try: - os.unlink(fname) - except OSError as e: - if e.errno == EISDIR: - os.rmdir(fname) - else: - raise + if os.path.isdir(fname): + remove = os.rmdir + else: + remove = os.unlink + remove(fname) self._maybe_notify(fname, self._inotify.IN_DELETE) return d.addTimeout(self._timeout, reactor) From 35fc563a6fde9274b5fa14b1259b64fc18c3c768 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 7 Mar 2019 11:42:12 -0500 Subject: [PATCH 77/93] Attempt to work-around watchdog bug --- src/allmydata/watchdog/_watchdog_541.py | 16 ++++++++++++++++ src/allmydata/watchdog/inotify.py | 3 +++ 2 files changed, 19 insertions(+) create mode 100644 src/allmydata/watchdog/_watchdog_541.py diff --git a/src/allmydata/watchdog/_watchdog_541.py b/src/allmydata/watchdog/_watchdog_541.py new file mode 100644 index 000000000..87686ce6d --- /dev/null +++ b/src/allmydata/watchdog/_watchdog_541.py @@ -0,0 +1,16 @@ +""" +Hotfix for https://github.com/gorakhargosh/watchdog/issues/541 +""" + +from watchdog.observers.fsevents import FSEventsEmitter + +# The class object has already been bundled up in the default arguments to +# FSEventsObserver.__init__. So mutate the class object (instead of replacing +# it with a safer version). +original_on_thread_stop = FSEventsEmitter.on_thread_stop +def safe_on_thread_stop(self): + if self.is_alive(): + return original_on_thread_stop(self) + +def patch(): + FSEventsEmitter.on_thread_stop = safe_on_thread_stop diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index 5db35d9dd..4b717aae6 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -53,6 +53,9 @@ from ..util.eliotutil import ( validateInstanceOf, ) +import ._watchdog_541 +_watchdog_541.patch() + NOT_STARTED = "NOT_STARTED" STARTED = "STARTED" STOPPING = "STOPPING" From 67ccd2148140153e57a92ba2d9ee0fb5839d91b6 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 7 Mar 2019 11:44:59 -0500 Subject: [PATCH 78/93] python syntax --- src/allmydata/watchdog/inotify.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index 4b717aae6..cce0a128f 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -53,7 +53,8 @@ from ..util.eliotutil import ( validateInstanceOf, ) -import ._watchdog_541 +from . import _watchdog_541 + _watchdog_541.patch() NOT_STARTED = "NOT_STARTED" From 984d27ab6245419c876240e6457080a992df9545 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 7 Mar 2019 14:44:24 -0500 Subject: [PATCH 79/93] simplify --- src/allmydata/test/test_magic_folder.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 7fb0d3c66..75b2e9780 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -2104,10 +2104,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall self.failUnlessEqual(metadata['version'], 2) def test_write_short_file(self): - d = DeferredContext(defer.succeed(None)) # Write something short enough for a LIT file. - d.addCallback(lambda ign: self._check_file(u"short", "test")) - return d.result + return self._check_file(u"short", "test") def test_magic_folder(self): d = DeferredContext(defer.succeed(None)) From 241b6cedfe6e5fc92f6d12087359cb02e096e82f Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Fri, 8 Mar 2019 09:27:24 -0500 Subject: [PATCH 80/93] Remove the skipped tests They're skipped because we don't need that functionality. If we need it in the future, we'll implement it with tests. --- src/allmydata/test/test_inotify.py | 155 ----------------------------- 1 file changed, 155 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 2b891f1f0..c2389ec7d 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -8,15 +8,12 @@ Tests for the inotify-alike implementation L{allmydata.watchdog}. # Note: See https://twistedmatrix.com/trac/ticket/8915 for a proposal # to avoid all of this duplicated code from Twisted. -import sys - from twisted.internet import defer, reactor from twisted.python import filepath, runtime from allmydata.frontends.magic_folder import get_inotify_module from .common import ( AsyncTestCase, - skip, skipIf, ) inotify = get_inotify_module() @@ -116,38 +113,6 @@ class INotifyTests(AsyncTestCase): return self._notificationTest(inotify.IN_CLOSE_WRITE, operation) - # The watchdog implementation makes it difficult to get this event. Also, - # the magic-folder implementation doesn't really *need* exactly this - # event. It would be nice to get some event on move, which watchdog gives - # us. But this test is overly specific for our purposes. - @skip("not available on watchdog") - def test_movedFrom(self): - """ - Moving a file out of a monitored directory sends an - C{inotify.IN_MOVED_FROM} event to the callback. - """ - def operation(path): - path.open("w").close() - path.moveTo(filepath.FilePath(self.mktemp())) - - return self._notificationTest(inotify.IN_MOVED_FROM, operation) - - - # Ditto the comment on test_movedFrom about watchdog here. - @skip("not available on watchdog") - def test_movedTo(self): - """ - Moving a file into a monitored directory sends an - C{inotify.IN_MOVED_TO} event to the callback. - """ - def operation(path): - p = filepath.FilePath(self.mktemp()) - p.touch() - p.moveTo(path) - - return self._notificationTest(inotify.IN_MOVED_TO, operation) - - def test_delete(self): """ Deleting a file in a monitored directory sends an @@ -168,47 +133,6 @@ class INotifyTests(AsyncTestCase): return notified - @skip("watchdog is differently recursive") - def test_simpleDeleteDirectory(self): - """ - L{inotify.INotify} removes a directory from the watchlist when - it's removed from the filesystem. - """ - subdir = self.dirname.child('test') - subdir.createDirectory() - - d = defer.Deferred() - - def _callback(wp, filename, mask): - # We are notified before the watch state is updated so we need to - # delay our check of that watch state a bit. - def _(): - try: - self.assertFalse( - self.inotify._isWatched(subdir), - "{} not un-watched. watches = {}".format(subdir, self.inotify._watches), - ) - d.callback(None) - except Exception: - d.errback() - reactor.callLater(0, _) - - checkMask = inotify.IN_ISDIR | inotify.IN_CREATE - self.inotify.watch( - self.dirname, - mask=checkMask, - callbacks=[_callback], - recursive=True, - ) - self.assertTrue( - self.inotify._isWatched(subdir), - "{} not watched. watches = {}".format(subdir, self.inotify._watches), - ) - subdir.remove() - - return d - - def test_humanReadableMask(self): """ L{inotify.humaReadableMask} translates all the possible event @@ -224,37 +148,6 @@ class INotifyTests(AsyncTestCase): set(['close_write', 'access', 'open'])) - @skip("not relevant") - def test_recursiveWatch(self): - """ - L{inotify.INotify.watch} with recursive==True will add all the - subdirectories under the given path to the watchlist. - """ - subdir = self.dirname.child('test') - subdir2 = subdir.child('test2') - subdir3 = subdir2.child('test3') - subdir3.makedirs() - dirs = [subdir, subdir2, subdir3] - self.inotify.watch(self.dirname, recursive=True) - # let's even call this twice so that we test that nothing breaks - self.inotify.watch(self.dirname, recursive=True) - for d in dirs: - self.assertTrue(self.inotify._isWatched(d)) - - - @skip("Based on Twisted implementation details; not relevant") - def test_connectionLostError(self): - """ - L{inotify.INotify.connectionLost} if there's a problem while closing - the fd shouldn't raise the exception but should log the error - """ - import os - in_ = inotify.INotify() - os.close(in_._fd) - in_.loseConnection() - self.flushLoggedErrors() - - def test_noAutoAddSubdirectory(self): """ L{inotify.INotify.watch} with autoAdd==False will stop inotify @@ -279,51 +172,3 @@ class INotifyTests(AsyncTestCase): d = defer.Deferred() subdir.createDirectory() return d - - - @skip("Not gonna implement autoAdd") - def test_complexSubdirectoryAutoAdd(self): - """ - L{inotify.INotify} with autoAdd==True for a watched path - generates events for every file or directory already present - in a newly created subdirectory under the watched one. - - This tests that we solve a race condition in inotify even though - we may generate duplicate events. - """ - calls = set() - def _callback(wp, filename, mask): - calls.add(filename) - if len(calls) == 6: - try: - self.assertTrue(self.inotify._isWatched(subdir)) - self.assertTrue(self.inotify._isWatched(subdir2)) - self.assertTrue(self.inotify._isWatched(subdir3)) - created = someFiles + [subdir, subdir2, subdir3] - created = {f.asBytesMode() for f in created} - self.assertEqual(len(calls), len(created)) - self.assertEqual(calls, created) - except Exception: - d.errback() - else: - d.callback(None) - - checkMask = inotify.IN_ISDIR | inotify.IN_CREATE - self.inotify.watch( - self.dirname, mask=checkMask, autoAdd=True, - callbacks=[_callback]) - subdir = self.dirname.child('test') - subdir2 = subdir.child('test2') - subdir3 = subdir2.child('test3') - d = defer.Deferred() - subdir3.makedirs() - - someFiles = [subdir.child('file1.dat'), - subdir2.child('file2.dat'), - subdir3.child('file3.dat')] - # Add some files in pretty much all the directories so that we - # see that we process all of them. - for i, filename in enumerate(someFiles): - filename.setContent( - filename.path.encode(sys.getfilesystemencoding())) - return d From 2205bf0fdd30d49d9f1748c01f8d65b8830d4703 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Fri, 8 Mar 2019 14:02:05 -0500 Subject: [PATCH 81/93] unused --- src/allmydata/test/test_magic_folder.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index 75b2e9780..b49b71a7f 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -3,7 +3,7 @@ import os, sys, time import stat, shutil, json import mock from os.path import join, exists, isdir -from errno import ENOENT, EISDIR +from errno import ENOENT from twisted.internet import defer, task, reactor from twisted.python.runtime import platform From 263755fb263fb2b87894d5566200fa4f936c95ef Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 11 Mar 2019 13:16:39 -0400 Subject: [PATCH 82/93] Watch before we start. Linux and macOS are happy to watch after starting. Our Windows support library can't deal with such a case, though. Linux is happy with the other order. I'm about to find out if macOS is. There are likely further Windows issues to deal with. --- src/allmydata/frontends/magic_folder.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 4a5dc8a15..1847fd459 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1181,8 +1181,8 @@ class Uploader(QueueMixin): with action.context(): d = DeferredContext(defer.succeed(None)) - d.addCallback(lambda ign: self._notifier.startReading()) d.addCallback(lambda ign: self._add_watch()) + d.addCallback(lambda ign: self._notifier.startReading()) d.addCallback(lambda ign: self._count('dirs_monitored')) d.addBoth(self._call_hook, 'started') return d.addActionFinish() From 3176b6f18ab77720854dee492c4bf0dbb7de98ef Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 11 Mar 2019 13:22:35 -0400 Subject: [PATCH 83/93] Create the watchdog Observer sooner This lets us watch before start which Windows seems to really want. --- src/allmydata/watchdog/inotify.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index cce0a128f..9b8f690e7 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -165,6 +165,7 @@ class INotify(PollMixin): self._callbacks = {} self._watches = {} self._state = NOT_STARTED + self._observer = Observer(timeout=self._pending_delay) def set_pending_delay(self, delay): Message.log(message_type=u"watchdog:inotify:set-pending-delay", delay=delay) @@ -178,7 +179,6 @@ class INotify(PollMixin): # XXX twisted.internet.inotify doesn't require watches to # be set before startReading is called. # _assert(len(self._callbacks) != 0, "no watch set") - self._observer = Observer(timeout=self._pending_delay) self._observer.start() self._state = STARTED except: From 64826aee37fb9ad09216a701f063c01dda906d6a Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 11 Mar 2019 13:45:44 -0400 Subject: [PATCH 84/93] Clean up stdout a bit --- src/allmydata/frontends/magic_folder.py | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 1847fd459..a863696b6 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -7,6 +7,7 @@ from datetime import datetime import time import ConfigParser +from twisted.python.log import msg as twmsg from twisted.python.filepath import FilePath from twisted.python.monkey import MonkeyPatcher from twisted.internet import defer, reactor, task @@ -1718,10 +1719,11 @@ class Downloader(QueueMixin, WriteFileMixin): while True: try: yield self._scan_remote_collective(scan_self=True) - # The integration tests watch for this log message to - # decide when it is safe to proceed. Clearly, we need - # better programmatic interrogation of magic-folder state. - print("Completed initial Magic Folder scan successfully ({})".format(self)) + # The integration tests watch for this log message (in the + # Twisted log) to decide when it is safe to proceed. + # Clearly, we need better programmatic interrogation of + # magic-folder state. + twmsg("Completed initial Magic Folder scan successfully ({})".format(self)) self._begin_processing() return except Exception: From 9ed019f8de801ddfaad5d6f021f848c595a5b514 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 11 Mar 2019 14:06:49 -0400 Subject: [PATCH 85/93] Give the tests a little more time. Windows may need it. --- src/allmydata/test/test_magic_folder.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/test/test_magic_folder.py b/src/allmydata/test/test_magic_folder.py index b49b71a7f..fa0118a96 100644 --- a/src/allmydata/test/test_magic_folder.py +++ b/src/allmydata/test/test_magic_folder.py @@ -613,7 +613,7 @@ class FileOperationsHelper(object): them sychronously. For the Real tests we have to wait for the actual inotify thing. """ - _timeout = 5.0 + _timeout = 30.0 def __init__(self, uploader, inject_events=False): self._uploader = uploader From fcb08b5a3a1fed287a7ab9e2baf04fc471141a7c Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 12 Mar 2019 15:00:15 -0400 Subject: [PATCH 86/93] Move these Eliot events somewhere reusable --- src/allmydata/watchdog/inotify.py | 17 ++--------------- 1 file changed, 2 insertions(+), 15 deletions(-) diff --git a/src/allmydata/watchdog/inotify.py b/src/allmydata/watchdog/inotify.py index 9b8f690e7..68a121a60 100644 --- a/src/allmydata/watchdog/inotify.py +++ b/src/allmydata/watchdog/inotify.py @@ -49,7 +49,8 @@ from allmydata.util.fake_inotify import humanReadableMask, \ _FLAG_TO_HUMAN from ..util.eliotutil import ( - INOTIFY_EVENTS, + MAYBE_NOTIFY, + CALLBACK, validateInstanceOf, ) @@ -68,13 +69,6 @@ _PATH = Field.for_types( u"The path an inotify event concerns.", ) -MAYBE_NOTIFY = ActionType( - u"watchdog:inotify:maybe-notify", - [], - [], - u"An inotify event is being considered for dispatch to an application handler.", -) - _EVENT = Field( u"event", lambda e: e.__class__.__name__, @@ -89,13 +83,6 @@ ANY_INOTIFY_EVENT = ActionType( u"An inotify event is being dispatched.", ) -CALLBACK = ActionType( - u"watchdog:inotify:callback", - [INOTIFY_EVENTS], - [], - u"An inotify event is being dispatched to an application callback." -) - class INotifyEventHandler(FileSystemEventHandler): def __init__(self, path, mask, callbacks, pending_delay): FileSystemEventHandler.__init__(self) From fef79cd4a324e1f5be936df0e4259a6dcf31668f Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 12 Mar 2019 15:56:47 -0400 Subject: [PATCH 87/93] re-use the _add_watch helper --- src/allmydata/frontends/magic_folder.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index a863696b6..4f2e5daa6 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1169,9 +1169,9 @@ class Uploader(QueueMixin): | IN_EXCL_UNLINK ) - def _add_watch(self): + def _add_watch(self, filepath): self._notifier.watch( - self._local_filepath, + filepath, mask=self.mask, callbacks=[self._notify], recursive=True, @@ -1182,7 +1182,7 @@ class Uploader(QueueMixin): with action.context(): d = DeferredContext(defer.succeed(None)) - d.addCallback(lambda ign: self._add_watch()) + d.addCallback(lambda ign: self._add_watch(self._local_filepath)) d.addCallback(lambda ign: self._notifier.startReading()) d.addCallback(lambda ign: self._count('dirs_monitored')) d.addBoth(self._call_hook, 'started') @@ -1465,7 +1465,7 @@ class Uploader(QueueMixin): return False elif pathinfo.isdir: if not getattr(self._notifier, 'recursive_includes_new_subdirectories', False): - self._notifier.watch(fp, mask=self.mask, callbacks=[self._notify], recursive=True) + self._add_watch(fp) DIRECTORY_PATHENTRY.log(pathentry=db_entry) if not is_new_file(pathinfo, db_entry): From 3978c45b04f37fb3bb2b21dfd0ad710cd2b656bb Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Tue, 12 Mar 2019 18:52:37 -0400 Subject: [PATCH 88/93] spit out the events as raw as we can --- src/allmydata/windows/inotify.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/windows/inotify.py b/src/allmydata/windows/inotify.py index b36051690..5e29a00ec 100644 --- a/src/allmydata/windows/inotify.py +++ b/src/allmydata/windows/inotify.py @@ -154,6 +154,7 @@ class FileNotifyInformation(object): bytes = self._read_dword(pos+8) s = Event(self._read_dword(pos+4), self.data[pos+12 : pos+12+bytes].decode('utf-16-le')) + Message.log(message_type="fni", info=repr(s)) next_entry_offset = self._read_dword(pos) yield s @@ -310,7 +311,6 @@ class INotify(PollMixin): if self._check_stop(): return for info in fni: - # print info path = self._path.preauthChild(info.filename) # FilePath with Unicode path if info.action == FILE_ACTION_MODIFIED and path.isdir(): Message.log( From dfd0c6e54cafb8fbcb916a09d083cbccdc5f6bbf Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 14 Mar 2019 10:20:00 -0400 Subject: [PATCH 89/93] fix "downloader" type in message type --- src/allmydata/frontends/magic_folder.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/frontends/magic_folder.py b/src/allmydata/frontends/magic_folder.py index 4f2e5daa6..a335c40b5 100644 --- a/src/allmydata/frontends/magic_folder.py +++ b/src/allmydata/frontends/magic_folder.py @@ -1808,7 +1808,7 @@ class Downloader(QueueMixin, WriteFileMixin): max_version = result[1]['version'] else: Message.log( - message_type="magic-folder:downlodaer:get-latest-file:failed", + message_type="magic-folder:downloader:get-latest-file:failed", ) return node, metadata collective_dirmap_d.addCallback(highest_version) From b14583f0e9c3df2d58e0b96d227c673224110db2 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 14 Mar 2019 10:22:49 -0400 Subject: [PATCH 90/93] Remove this broken ignore_count thing The only purpose it serves to make the tests invalid and useless. --- src/allmydata/test/test_inotify.py | 11 +++-------- 1 file changed, 3 insertions(+), 8 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index c2389ec7d..3feebdb20 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -26,7 +26,6 @@ class INotifyTests(AsyncTestCase): L{inotify.INotify}. """ def setUp(self): - self.ignore_count = 0 self.dirname = filepath.FilePath(self.mktemp()) self.dirname.createDirectory() self.inotify = inotify.INotify() @@ -35,7 +34,7 @@ class INotifyTests(AsyncTestCase): return super(INotifyTests, self).setUp() - def _notificationTest(self, mask, operation, expectedPath=None, ignore_count=0): + def _notificationTest(self, mask, operation, expectedPath=None): """ Test notification from some filesystem operation. @@ -54,12 +53,8 @@ class INotifyTests(AsyncTestCase): @return: A L{Deferred} which fires successfully when the expected event has been received or fails otherwise. """ - assert ignore_count >= 0 if expectedPath is None: expectedPath = self.dirname.child("foo.bar") - if ignore_count > 0: - self.ignore_count -= 1 - return notified = defer.Deferred() def cbNotified(result): (watch, filename, events) = result @@ -86,7 +81,7 @@ class INotifyTests(AsyncTestCase): with path.open("w") as fObj: fObj.write(b'foo') - return self._notificationTest(inotify.IN_MODIFY, operation, ignore_count=1) + return self._notificationTest(inotify.IN_MODIFY, operation) def test_attrib(self): @@ -98,7 +93,7 @@ class INotifyTests(AsyncTestCase): path.touch() path.touch() - return self._notificationTest(inotify.IN_ATTRIB, operation, ignore_count=1) + return self._notificationTest(inotify.IN_ATTRIB, operation) def test_closeWrite(self): From 2cb710ac1ed4f7a76e4cbeb5387555bbdad5ec8b Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 14 Mar 2019 10:23:52 -0400 Subject: [PATCH 91/93] Just touch the path once --- src/allmydata/test/test_inotify.py | 1 - 1 file changed, 1 deletion(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 3feebdb20..473e7e08f 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -91,7 +91,6 @@ class INotifyTests(AsyncTestCase): """ def operation(path): path.touch() - path.touch() return self._notificationTest(inotify.IN_ATTRIB, operation) From 5141105441abbf898e948c6b4cffad64ca7baaed Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 14 Mar 2019 10:24:56 -0400 Subject: [PATCH 92/93] Fix typo --- src/allmydata/test/test_inotify.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 473e7e08f..2ce5396ce 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -129,8 +129,8 @@ class INotifyTests(AsyncTestCase): def test_humanReadableMask(self): """ - L{inotify.humaReadableMask} translates all the possible event - masks to a human readable string. + L{inotify.humanReadableMask} translates all the possible event masks to a + human readable string. """ for mask, value in inotify._FLAG_TO_HUMAN: self.assertEqual(inotify.humanReadableMask(mask)[0], value) From 365ff1a02cbd3a8ac2511e8114a55ee7090b133e Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Thu, 14 Mar 2019 10:27:48 -0400 Subject: [PATCH 93/93] explain why we need to touch() twice --- src/allmydata/test/test_inotify.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/allmydata/test/test_inotify.py b/src/allmydata/test/test_inotify.py index 2ce5396ce..9f618a34a 100644 --- a/src/allmydata/test/test_inotify.py +++ b/src/allmydata/test/test_inotify.py @@ -90,6 +90,9 @@ class INotifyTests(AsyncTestCase): sends an C{inotify.IN_ATTRIB} event to the callback. """ def operation(path): + # Create the file. + path.touch() + # Modify the file's attributes. path.touch() return self._notificationTest(inotify.IN_ATTRIB, operation)