Merge pull request #575 from tahoe-lafs/2965.erroneous-conflicts-at-startup

Avoid some start-up time erroneous Magic-Folder conflict files

Fixes: ticket:2965

integration/test_magic_folder.py

@@ -395,3 +395,67 @@ def test_edmond_uploads_then_restarts(reactor, request, temp_dir, introducer_fur
         assert exists(join(magic_folder, "its_a_file"))
         assert not exists(join(magic_folder, "its_a_file.backup"))
         time.sleep(1)
+
+
+@pytest_twisted.inlineCallbacks
+def test_alice_adds_files_while_bob_is_offline(reactor, request, temp_dir, magic_folder):
+    """
+    Alice can add new files to a magic folder while Bob is offline.  When Bob
+    comes back online his copy is updated to reflect the new files.
+    """
+    alice_magic_dir, bob_magic_dir = magic_folder
+    alice_node_dir = join(temp_dir, "alice")
+    bob_node_dir = join(temp_dir, "bob")
+
+    # Take Bob offline.
+    yield util.cli(reactor, bob_node_dir, "stop")
+
+    # Create a couple files in Alice's local directory.
+    some_files = list(
+        (name * 3) + ".added-while-offline"
+        for name
+        in "xyz"
+    )
+    for name in some_files:
+        with open(join(alice_magic_dir, name), "w") as f:
+            f.write(name + " some content")
+
+    good = False
+    for i in range(15):
+        status = yield util.magic_folder_cli(reactor, alice_node_dir, "status")
+        good = status.count(".added-while-offline (36 B): good, version=0") == len(some_files) * 2
+        if good:
+            # We saw each file as having a local good state and a remote good
+            # state.  That means we're ready to involve Bob.
+            break
+        else:
+            time.sleep(1.0)
+
+    assert good, (
+        "Timed out waiting for good Alice state.  Last status:\n{}".format(status)
+    )
+
+    # Start Bob up again
+    magic_text = 'Completed initial Magic Folder scan successfully'
+    yield util._run_node(reactor, bob_node_dir, request, magic_text)
+
+    yield util.await_files_exist(
+        list(
+            join(bob_magic_dir, name)
+            for name
+            in some_files
+        ),
+        await_all=True,
+    )
+    # Let it settle.  It would be nicer to have a readable status output we
+    # could query.  Parsing the current text format is more than I want to
+    # deal with right now.
+    time.sleep(1.0)
+    conflict_files = list(name + ".conflict" for name in some_files)
+    assert all(
+        list(
+            not exists(join(bob_magic_dir, name))
+            for name
+            in conflict_files
+        ),
+    )

integration/util.py

@@ -303,7 +303,7 @@ def await_files_exist(paths, timeout=15, await_all=False):
     an Exception is raised
     """
     start_time = time.time()
-    while time.time() - start_time < 15.0:
+    while time.time() - start_time < timeout:
         print("  waiting for: {}".format(' '.join(paths)))
         found = [p for p in paths if exists(p)]
         print("found: {}".format(found))
@@ -329,3 +329,19 @@ def await_file_vanishes(path, timeout=10):
             return
         time.sleep(1)
     raise FileShouldVanishException(path, timeout)
+
+
+def cli(reactor, node_dir, *argv):
+    proto = _CollectOutputProtocol()
+    reactor.spawnProcess(
+        proto,
+        sys.executable,
+        [
+            sys.executable, '-m', 'allmydata.scripts.runner',
+            '--node-directory', node_dir,
+        ] + list(argv),
+    )
+    return proto.done
+
+def magic_folder_cli(reactor, node_dir, *argv):
+    return cli(reactor, node_dir, "magic-folder", *argv)

newsfragments/2965.bugfix

@@ -0,0 +1 @@
+Magic-Folders now creates spurious conflict files in fewer cases.  In particular, if files are added to the folder while a client is offline, that client will not create conflict files for all those new files when it starts up.

src/allmydata/frontends/magic_folder.py

@@ -973,8 +973,17 @@ class QueueMixin(HookMixin):
         with action.context():
             d = DeferredContext(defer.Deferred())
 
-            # adds items to our deque
-            d.addCallback(lambda ignored: self._perform_scan())
+            # During startup we scanned the collective for items to download.
+            # If we found work to do, we do not need to perform another scan
+            # here.  More importantly, the logic for determining which items
+            # to download is *not correct* in the case where two scans are
+            # performed with no intermediate emptying of the work queue.
+            # Therefore, skip the scan any time there is queued work.  The
+            # only time we expect there to be any, though, is on the first
+            # time through this loop.
+            if not self._deque:
+                # adds items to our deque
+                d.addCallback(lambda ignored: self._perform_scan())
 
             # process anything in our queue
             d.addCallback(lambda ignored: self._process_deque())
@@ -1732,7 +1741,7 @@ class Downloader(QueueMixin, WriteFileMixin):
                         "Last tried at %s" % self.nice_current_time(),
                     )
                     write_traceback()
-                    yield task.deferLater(self._clock, self._poll_interval, lambda: None)
+                    yield task.deferLater(self._clock, self._scan_delay(), lambda: None)
 
     def nice_current_time(self):
         return format_time(datetime.fromtimestamp(self._clock.seconds()).timetuple())
@@ -1854,6 +1863,7 @@ class Downloader(QueueMixin, WriteFileMixin):
 
     @eliotutil.log_call_deferred(SCAN_REMOTE_COLLECTIVE.action_type)
     def _scan_remote_collective(self, scan_self=False):
+        precondition(not self._deque, "Items in _deque invalidate should_download logic")
         scan_batch = {}  # path -> [(filenode, metadata)]
         d = DeferredContext(self._collective_dirnode.list())
         def scan_collective(dirmap):

src/allmydata/test/test_magic_folder.py

@@ -1084,50 +1084,54 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         # now, we ONLY want to do the scan, not a full iteration of
         # the process loop. So we do just the scan part "by hand" in
         # Bob's downloader
-        yield self.bob_magicfolder.downloader._perform_scan()
-        # while we're delving into internals, I guess we might as well
-        # confirm that we did queue up an item to download
-        self.assertEqual(1, len(self.bob_magicfolder.downloader._deque))
+        with start_action(action_type=u"test:perform-scan"):
+            yield self.bob_magicfolder.downloader._perform_scan()
+            # while we're delving into internals, I guess we might as well
+            # confirm that we did queue up an item to download
+            self.assertEqual(1, len(self.bob_magicfolder.downloader._deque))
 
-        # break all the servers so the download fails. the count is 2
-        # because the "full iteration" will do a scan (downloading the
-        # metadata file) and then process the deque (trying to
-        # download the item we queued up already)
+        # break all the servers so the download fails.  count=1 because we
+        # only want the download attempted by _process_deque to fail.  After
+        # that, we want it to work again.
         for server_id in self.g.get_all_serverids():
-            self.g.break_server(server_id, count=2)
+            self.g.break_server(server_id, count=1)
 
-        # now let bob try to do the download
-        yield iterate(self.bob_magicfolder)
+        # now let bob try to do the download.  Reach in and call
+        # _process_deque directly because we are already half-way through a
+        # logical iteration thanks to the _perform_scan call above.
+        with start_action(action_type=u"test:process-deque"):
+            yield self.bob_magicfolder.downloader._process_deque()
 
-        self.eliot_logger.flushTracebacks(UnrecoverableFileError)
-        logged = self.eliot_logger.flushTracebacks(NoSharesError)
-        self.assertEqual(
-            1,
-            len(logged),
-            "Got other than expected single NoSharesError: {}".format(logged),
-        )
+            self.eliot_logger.flushTracebacks(UnrecoverableFileError)
+            logged = self.eliot_logger.flushTracebacks(NoSharesError)
+            self.assertEqual(
+                1,
+                len(logged),
+                "Got other than expected single NoSharesError: {}".format(logged),
+            )
 
-        # ...however Bob shouldn't have downloaded anything
-        self._check_version_in_local_db(self.bob_magicfolder, u"blam", 0)
-        # bob should *not* have downloaded anything, as we failed all the servers
-        self.failUnlessReallyEqual(
-            self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client),
-            0
-        )
-        self.failUnlessReallyEqual(
-            self._get_count('downloader.objects_failed', client=self.bob_magicfolder._client),
-            1
-        )
+            # ...however Bob shouldn't have downloaded anything
+            self._check_version_in_local_db(self.bob_magicfolder, u"blam", 0)
+            # bob should *not* have downloaded anything, as we failed all the servers
+            self.failUnlessReallyEqual(
+                self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client),
+                0
+            )
+            self.failUnlessReallyEqual(
+                self._get_count('downloader.objects_failed', client=self.bob_magicfolder._client),
+                1
+            )
 
-        # now we let Bob try again
-        yield iterate(self.bob_magicfolder)
+        with start_action(action_type=u"test:iterate"):
+            # now we let Bob try again
+            yield iterate(self.bob_magicfolder)
 
-        # ...and he should have succeeded
-        self.failUnlessReallyEqual(
-            self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client),
-            1
-        )
-        yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 0)
+            # ...and he should have succeeded
+            self.failUnlessReallyEqual(
+                self._get_count('downloader.objects_downloaded', client=self.bob_magicfolder._client),
+                1
+            )
+            yield self._check_version_in_dmd(self.bob_magicfolder, u"blam", 0)
 
     @inline_callbacks
     def test_conflict_local_change_fresh(self):