A fair bit more Eliot conversion

src/allmydata/frontends/magic_folder.py

@@ -7,6 +7,7 @@ from datetime import datetime
 import time
 import ConfigParser
 
+from twisted.python.filepath import FilePath
 from twisted.python.monkey import MonkeyPatcher
 from twisted.internet import defer, reactor, task
 from twisted.internet.error import AlreadyCancelled
@@ -424,7 +425,7 @@ class MagicFolder(service.MultiService):
 
 _NICKNAME = Field.for_types(
     u"nickname",
-    [unicode],
+    [unicode, bytes],
     u"A Magic-Folder participant nickname.",
 )
 
@@ -494,6 +495,81 @@ MAGIC_FOLDER_STOP = ActionType(
     u"A Magic-Folder is being stopped.",
 )
 
+MAYBE_UPLOAD = MessageType(
+    u"magic-folder:maybe-upload",
+    [eliotutil.RELPATH],
+    u"A decision is being made about whether to upload a file.",
+)
+
+PENDING = Field.for_types(
+    u"pending",
+    [list],
+    u"The paths which are pending processing.",
+)
+
+REMOVE_FROM_PENDING = ActionType(
+    u"magic-folder:remove-from-pending",
+    [eliotutil.RELPATH, PENDING],
+    [],
+    u"An item being processed is being removed from the pending set.",
+)
+
+PATH = Field(
+    u"path",
+    lambda fp: quote_filepath(fp),
+    u"A local filesystem path.",
+    eliotutil.validateInstanceOf(FilePath),
+)
+
+NOTIFIED_OBJECT_DISAPPEARED = MessageType(
+    u"magic-folder:notified-object-disappeared",
+    [PATH],
+    u"A path which generated a notification was not found on the filesystem.  This is normal.",
+)
+
+NOT_UPLOADING = MessageType(
+    u"magic-folder:not-uploading",
+    [],
+    u"An item being processed is not going to be uploaded.",
+)
+
+SYMLINK = MessageType(
+    u"magic-folder:symlink",
+    [PATH],
+    u"An item being processed was a symlink and is being skipped",
+)
+
+CREATED_DIRECTORY = Field.for_types(
+    u"created_directory",
+    [unicode],
+    u"The relative path of a newly created directory in a magic-folder.",
+)
+
+PROCESS_DIRECTORY = ActionType(
+    u"magic-folder:process-directory",
+    [],
+    [CREATED_DIRECTORY],
+    u"An item being processed was a directory.",
+)
+
+NOT_NEW_DIRECTORY = MessageType(
+    u"magic-folder:not-new-directory",
+    [],
+    u"A directory item being processed was found to not be new.",
+)
+
+NOT_NEW_FILE = MessageType(
+    u"magic-folder:not-new-file",
+    [],
+    u"A file item being processed was found to not be new (or changed).",
+)
+
+SPECIAL_FILE = MessageType(
+    u"magic-folder:special-file",
+    [],
+    u"An item being processed was found to be of a special type which is not supported.",
+)
+
 class QueueMixin(HookMixin):
     """
     A parent class for Uploader and Downloader that handles putting
@@ -939,23 +1015,22 @@ class Uploader(QueueMixin):
         precondition(not relpath_u.endswith(u'/'), relpath_u)
 
         def _maybe_upload(ign, now=None):
-            self._log("_maybe_upload: relpath_u=%r, now=%r" % (relpath_u, now))
+            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))
 
-            self._log("about to remove %r from pending set %r" %
-                      (relpath_u, self._pending))
             try:
+                with REMOVE_FROM_PENDING(relpath=relpath_u, pending=list(self._pending)):
                     self._pending.remove(relpath_u)
             except KeyError:
-                self._log("WRONG that %r wasn't in pending" % (relpath_u,))
+                pass
             encoded_path_u = magicpath.path2magic(relpath_u)
 
             if not pathinfo.exists:
                 # FIXME merge this with the 'isfile' case.
-                self._log("notified object %s disappeared (this is normal)" % quote_filepath(fp))
+                NOTIFIED_OBJECT_DISAPPEARED.log(path=fp)
                 self._count('objects_disappeared')
 
                 db_entry = self._db.get_db_entry(relpath_u)
@@ -967,7 +1042,7 @@ class Uploader(QueueMixin):
                 if is_new_file(pathinfo, db_entry):
                     new_version = db_entry.version + 1
                 else:
-                    self._log("Not uploading %r" % (relpath_u,))
+                    NOT_UPLOADING.log()
                     self._count('objects_not_uploaded')
                     return False
 
@@ -1006,12 +1081,12 @@ class Uploader(QueueMixin):
                     metadata['last_uploaded_uri'] = db_entry.last_uploaded_uri
 
                 empty_uploadable = Data("", self._client.convergence)
-                d2 = self._upload_dirnode.add_file(
+                d2 = DeferredContext(self._upload_dirnode.add_file(
                     encoded_path_u, empty_uploadable,
                     metadata=metadata,
                     overwrite=True,
                     progress=item.progress,
-                )
+                ))
 
                 def _add_db_entry(filenode):
                     filecap = filenode.get_uri()
@@ -1030,40 +1105,36 @@ class Uploader(QueueMixin):
                     self._count('files_uploaded')
                 d2.addCallback(_add_db_entry)
                 d2.addCallback(lambda ign: True)
-                return d2
+                return d2.result
             elif pathinfo.islink:
-                self.warn("WARNING: cannot upload symlink %s" % quote_filepath(fp))
+                SYMLINK.log(path=fp)
                 return False
             elif pathinfo.isdir:
-                self._log("ISDIR")
+                with PROCESS_DIRECTORY().context() as action:
                     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)
                     self._log("isdir dbentry %r" % (db_entry,))
                     if not is_new_file(pathinfo, db_entry):
-                    self._log("NOT A NEW FILE")
+                        NOT_NEW_DIRECTORY.log()
                         return False
 
                     uploadable = Data("", self._client.convergence)
                     encoded_path_u += magicpath.path2magic(u"/")
-                self._log("encoded_path_u =  %r" % (encoded_path_u,))
+                    upload_d = DeferredContext(self._upload_dirnode.add_file(
-                upload_d = self._upload_dirnode.add_file(
                         encoded_path_u, uploadable,
                         metadata={"version": 0},
                         overwrite=True,
                         progress=item.progress,
-                )
+                    ))
                     def _dir_succeeded(ign):
-                    self._log("created subdirectory %r" % (relpath_u,))
+                        action.add_success_fields(created_directory=relpath_u)
                         self._count('directories_created')
-                def _dir_failed(f):
+                    upload_d.addCallback(_dir_succeeded)
-                    self._log("failed to create subdirectory %r" % (relpath_u,))
-                    return f
-                upload_d.addCallbacks(_dir_succeeded, _dir_failed)
                     upload_d.addCallback(lambda ign: self._scan(relpath_u))
                     upload_d.addCallback(lambda ign: True)
-                return upload_d
+                    return upload_d.addActionFinish()
             elif pathinfo.isfile:
                 db_entry = self._db.get_db_entry(relpath_u)
 
@@ -1074,7 +1145,7 @@ class Uploader(QueueMixin):
                 elif is_new_file(pathinfo, db_entry):
                     new_version = db_entry.version + 1
                 else:
-                    self._log("Not uploading %r" % (relpath_u,))
+                    NOT_NEW_FILE.log()
                     self._count('objects_not_uploaded')
                     return False
 
@@ -1090,12 +1161,12 @@ class Uploader(QueueMixin):
                         metadata['last_uploaded_uri'] = db_entry.last_uploaded_uri
 
                 uploadable = FileName(unicode_from_filepath(fp), self._client.convergence)
-                d2 = self._upload_dirnode.add_file(
+                d2 = DeferredContext(self._upload_dirnode.add_file(
                     encoded_path_u, uploadable,
                     metadata=metadata,
                     overwrite=True,
                     progress=item.progress,
-                )
+                ))
 
                 def _add_db_entry(filenode):
                     filecap = filenode.get_uri()
@@ -1114,15 +1185,14 @@ class Uploader(QueueMixin):
                     self._count('files_uploaded')
                     return True
                 d2.addCallback(_add_db_entry)
-                return d2
+                return d2.addActionFinish()
             else:
-                self.warn("WARNING: cannot process special file %s" % quote_filepath(fp))
+                SPECIAL_FILE.log()
                 return False
 
         d.addCallback(_maybe_upload)
 
         def _succeeded(res):
-            self._log("_succeeded(%r)" % (res,))
             if res:
                 self._count('objects_succeeded')
             # TODO: maybe we want the status to be 'ignored' if res is False
@@ -1130,7 +1200,6 @@ class Uploader(QueueMixin):
             return res
         def _failed(f):
             self._count('objects_failed')
-            self._log("%s while processing %r" % (f, relpath_u))
             item.set_status('failure', self._clock.seconds())
             return f
         d.addCallbacks(_succeeded, _failed)

src/allmydata/test/test_magic_folder.py

@@ -781,8 +781,9 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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)
 
+    @capture_logging(None)
     @defer.inlineCallbacks
-    def test_alice_sees_bobs_delete_with_error(self):
+    def test_alice_sees_bobs_delete_with_error(self, logger):
         # alice creates a file, bob deletes it -- and we also arrange
         # for Alice's file to have "gone missing" as well.
         alice_fname = os.path.join(self.alice_magic_dir, 'blam')
@@ -839,8 +840,9 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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)
 
+    @capture_logging(None)
     @defer.inlineCallbacks
-    def test_alice_create_bob_update(self):
+    def test_alice_create_bob_update(self, logger):
         alice_fname = os.path.join(self.alice_magic_dir, 'blam')
         bob_fname = os.path.join(self.bob_magic_dir, 'blam')
 
@@ -879,8 +881,9 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         yield self._check_version_in_dmd(self.alice_magicfolder, u"blam", 1)
         self._check_version_in_local_db(self.alice_magicfolder, u"blam", 1)
 
+    @capture_logging(None)
     @defer.inlineCallbacks
-    def test_download_retry(self):
+    def test_download_retry(self, logger):
         alice_fname = os.path.join(self.alice_magic_dir, 'blam')
         # bob_fname = os.path.join(self.bob_magic_dir, 'blam')
 
@@ -931,8 +934,9 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         )
         yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 0)
 
+    @capture_logging(None)
     @defer.inlineCallbacks
-    def test_conflict_local_change_fresh(self):
+    def test_conflict_local_change_fresh(self, logger):
         alice_fname = os.path.join(self.alice_magic_dir, 'localchange0')
         bob_fname = os.path.join(self.bob_magic_dir, 'localchange0')
 
@@ -957,8 +961,9 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         # ...so now bob should produce a conflict
         self.assertTrue(os.path.exists(bob_fname + '.conflict'))
 
+    @capture_logging(None)
     @defer.inlineCallbacks
-    def test_conflict_local_change_existing(self):
+    def test_conflict_local_change_existing(self, logger):
         alice_fname = os.path.join(self.alice_magic_dir, 'localchange1')
         bob_fname = os.path.join(self.bob_magic_dir, 'localchange1')
 
@@ -995,8 +1000,9 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         # ...so now bob should produce a conflict
         self.assertTrue(os.path.exists(bob_fname + '.conflict'))
 
+    @capture_logging(None)
     @defer.inlineCallbacks
-    def test_alice_delete_and_restore(self):
+    def test_alice_delete_and_restore(self, logger):
         alice_fname = os.path.join(self.alice_magic_dir, 'blam')
         bob_fname = os.path.join(self.bob_magic_dir, 'blam')
 
@@ -1072,7 +1078,8 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
 
     # XXX this should be shortened -- as in, any cases not covered by
     # the other tests in here should get their own minimal test-case.
-    def test_alice_bob(self):
+    @capture_logging(None)
+    def test_alice_bob(self, logger):
         if sys.platform == "win32":
             raise unittest.SkipTest("Still inotify problems on Windows (FIXME)")
 
@@ -1507,7 +1514,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
         self._createdb()
 
     @defer.inlineCallbacks
-    def test_scan_once_on_startup(self):
+    @capture_logging(None)
+    def test_scan_once_on_startup(self, logger):
         # What is this test? Maybe it is just a stub and needs finishing.
         self.magicfolder.uploader._clock.advance(99)
 
@@ -1518,7 +1526,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
         yield self._check_downloader_count('objects_failed', 0, magic=self.magicfolder)
         yield self._check_downloader_count('objects_downloaded', 0, magic=self.magicfolder)
 
-    def test_db_persistence(self):
+    @capture_logging(None)
+    def test_db_persistence(self, logger):
         """Test that a file upload creates an entry in the database."""
 
         fileutil.make_dirs(self.basedir)
@@ -1565,7 +1574,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
         d.addCallback(lambda ign: self.failUnlessReallyEqual(self._get_count('uploader.dirs_monitored'), 0))
         return d
 
-    def test_move_tree(self):
+    @capture_logging(None)
+    def test_move_tree(self, logger):
         """
         create an empty directory tree and 'mv' it into the magic folder,
         noting the new directory and uploading it.
@@ -1639,7 +1649,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
         return d
     test_move_tree.todo = "fails on certain linux flavors: see ticket #2834"
 
-    def test_persistence(self):
+    @capture_logging(None)
+    def test_persistence(self, logger):
         """
         Perform an upload of a given file and then stop the client.
         Start a new client and magic-folder service... and verify that the file is NOT uploaded
@@ -1678,7 +1689,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
     # what each test uses for setup, etc. :(
 
     @defer.inlineCallbacks
-    def test_delete(self):
+    @capture_logging(None)
+    def test_delete(self, logger):
         # setup: create a file 'foo'
         path = os.path.join(self.local_dir, u'foo')
         yield self.fileops.write(path, 'foo\n')
@@ -1701,7 +1713,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
         self.failUnlessEqual(metadata['version'], 1)
 
     @defer.inlineCallbacks
-    def test_batched_process(self):
+    @capture_logging(None)
+    def test_batched_process(self, logger):
         """
         status APIs correctly function when there are 2 items queued at
         once for processing
@@ -1733,7 +1746,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
         self.assertEqual(upstatus0, upstatus1)
 
     @defer.inlineCallbacks
-    def test_real_notify_failure(self):
+    @capture_logging(None)
+    def test_real_notify_failure(self, logger):
         """
         Simulate an exception from the _real_notify helper in
         magic-folder's uploader, confirming error-handling works.
@@ -1772,7 +1786,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
         self.assertTrue(len(errors) >= 1)
 
     @defer.inlineCallbacks
-    def test_delete_and_restore(self):
+    @capture_logging(None)
+    def test_delete_and_restore(self, logger):
         # setup: create a file
         path = os.path.join(self.local_dir, u'foo')
         yield self.fileops.write(path, 'foo\n')
@@ -1800,7 +1815,8 @@ class SingleMagicFolderTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Reall
         self.assertTrue(node is not None, "Failed to find %r in DMD" % (path,))
         self.failUnlessEqual(metadata['version'], 2)
 
-    def test_magic_folder(self):
+    @capture_logging(None)
+    def test_magic_folder(self, logger):
         d = defer.succeed(None)
         # Write something short enough for a LIT file.
         d.addCallback(lambda ign: self._check_file(u"short", "test"))
@@ -1844,7 +1860,8 @@ class MockTest(SingleMagicFolderTestMixin, unittest.TestCase):
         self.patch(magic_folder, 'get_inotify_module', lambda: self.inotify)
         return d
 
-    def test_errors(self):
+    @capture_logging(None)
+    def test_errors(self, logger):
         self.set_up_grid(oneshare=True)
 
         errors_dir = abspath_expanduser_unicode(u"errors_dir", base=self.basedir)
@@ -1882,7 +1899,8 @@ class MockTest(SingleMagicFolderTestMixin, unittest.TestCase):
         d.addCallback(_check_errors)
         return d
 
-    def test_write_downloaded_file(self):
+    @capture_logging(None)
+    def test_write_downloaded_file(self, logger):
         workdir = fileutil.abspath_expanduser_unicode(u"cli/MagicFolder/write-downloaded-file")
         local_file = fileutil.abspath_expanduser_unicode(u"foobar", base=workdir)
 
@@ -1927,7 +1945,8 @@ class MockTest(SingleMagicFolderTestMixin, unittest.TestCase):
         # .tmp file shouldn't exist
         self.failIf(os.path.exists(local_file + u".tmp"))
 
-    def test_periodic_full_scan(self):
+    @capture_logging(None)
+    def test_periodic_full_scan(self, logger):
         """
         Create a file in a subdir without doing a notify on it and
         fast-forward time to prove we do a full scan periodically.
@@ -1955,7 +1974,8 @@ class MockTest(SingleMagicFolderTestMixin, unittest.TestCase):
         d.addCallback(lambda ign: self.failUnlessReallyEqual(self._get_count('uploader.files_uploaded'), 1))
         return d
 
-    def test_statistics(self):
+    @capture_logging(None)
+    def test_statistics(self, logger):
         d = defer.succeed(None)
         # Write something short enough for a LIT file.
         d.addCallback(lambda ign: self._check_file(u"short", "test"))

src/allmydata/util/eliotutil.py

@@ -208,7 +208,7 @@ LAST_DOWNLOADED_URI = Field.for_types(
 
 LAST_DOWNLOADED_TIMESTAMP = Field.for_types(
     u"last_downloaded_timestamp",
-    [float],
+    [float, int, long],
     u"(XXX probably not really, don't trust this) The timestamp of the last download of this file.",
 )