Merge branch 'pr448'

integration/test_smoke.py

@@ -1,3 +1,4 @@
+import sys
 import time
 import shutil
 from os import mkdir, unlink, listdir
@@ -113,7 +114,7 @@ def test_bob_creates_alice_deletes_bob_restores(magic_folder):
     # .. she previously deleted it? does that really make sense)
 
     util.await_file_contents(
-        join(alice_dir, "boom.conflict"),
+        join(alice_dir, "boom"),
         "bob wrote this again, because reasons",
     )
 
@@ -189,3 +190,110 @@ def test_bob_conflicts_with_alice_preexisting(magic_folder):
     util.await_file_contents(join(bob_dir, 'beta'), "this is bob's beta\n")
     util.await_file_contents(join(alice_dir, 'beta'), "this is bob's beta\n")
     util.await_file_contents(join(alice_dir, 'beta.backup'), "this is alice's beta\n")
+
+
+@pytest.inlineCallbacks
+def test_edmond_uploads_then_restarts(reactor, request, temp_dir, introducer_furl, flog_gatherer, storage_nodes):
+    """
+    ticket 2880: if a magic-folder client uploads something, then
+    re-starts a spurious .backup file should not appear
+    """
+
+    edmond_dir = join(temp_dir, 'edmond')
+    edmond = yield util._create_node(
+        reactor, request, temp_dir, introducer_furl, flog_gatherer,
+        "edmond", web_port="tcp:9985:interface=localhost",
+        storage=False,
+    )
+
+
+    magic_folder = join(temp_dir, 'magic-edmond')
+    mkdir(magic_folder)
+    created = False
+    # create a magic-folder
+    # (how can we know that the grid is ready?)
+    for _ in range(10):  # try 10 times
+        try:
+            proto = util._CollectOutputProtocol()
+            transport = reactor.spawnProcess(
+                proto,
+                sys.executable,
+                [
+                    sys.executable, '-m', 'allmydata.scripts.runner',
+                    'magic-folder', 'create',
+                    '--poll-interval', '2',
+                    '--basedir', edmond_dir,
+                    'magik:',
+                    'edmond_magic',
+                    magic_folder,
+                ]
+            )
+            yield proto.done
+            created = True
+            break
+        except Exception as e:
+            print("failed to create magic-folder: {}".format(e))
+            time.sleep(1)
+
+    assert created, "Didn't create a magic-folder"
+
+    # to actually-start the magic-folder we have to re-start
+    edmond.signalProcess('TERM')
+    yield edmond._protocol.exited
+    time.sleep(1)
+    edmond = yield util._run_node(reactor, edmond._node_dir, request, 'Completed initial Magic Folder scan successfully')
+
+    # add a thing to the magic-folder
+    with open(join(magic_folder, "its_a_file"), "w") as f:
+        f.write("edmond wrote this")
+
+    # fixme, do status-update attempts in a loop below
+    time.sleep(5)
+
+    # let it upload; poll the HTTP magic-folder status API until it is
+    # uploaded
+    from allmydata.scripts.magic_folder_cli import _get_json_for_fragment
+
+    with open(join(edmond_dir, u'private', u'api_auth_token'), 'rb') as f:
+        token = f.read()
+
+    uploaded = False
+    for _ in range(10):
+        options = {
+            "node-url": open(join(edmond_dir, u'node.url'), 'r').read().strip(),
+        }
+        try:
+            magic_data = _get_json_for_fragment(
+                options,
+                'magic_folder?t=json',
+                method='POST',
+                post_args=dict(
+                    t='json',
+                    name='default',
+                    token=token,
+                )
+            )
+            for mf in magic_data:
+                if mf['status'] == u'success' and mf['path'] == u'its_a_file':
+                    uploaded = True
+                    break
+        except Exception as e:
+            time.sleep(1)
+
+    assert uploaded, "expected to upload 'its_a_file'"
+
+    # re-starting edmond right now would "normally" trigger the 2880 bug
+
+    # kill edmond
+    edmond.signalProcess('TERM')
+    yield edmond._protocol.exited
+    time.sleep(1)
+    edmond = yield util._run_node(reactor, edmond._node_dir, request, 'Completed initial Magic Folder scan successfully')
+
+    # XXX how can we say for sure if we've waited long enough? look at
+    # tail of logs for magic-folder ... somethingsomething?
+    print("waiting 20 seconds to see if a .backup appears")
+    for _ in range(20):
+        assert exists(join(magic_folder, "its_a_file"))
+        assert not exists(join(magic_folder, "its_a_file.backup"))
+        time.sleep(1)

integration/util.py

@@ -52,7 +52,7 @@ class _CollectOutputProtocol(ProcessProtocol):
         self.output.write(data)
 
     def errReceived(self, data):
-        print("ERR", data)
+        print("ERR: {}".format(data))
         self.output.write(data)
 
 
@@ -99,7 +99,7 @@ class _MagicTextProtocol(ProcessProtocol):
         self._output.write(data)
         if not self.magic_seen.called and self._magic_text in self._output.getvalue():
             print("Saw '{}' in the logs".format(self._magic_text))
-            self.magic_seen.callback(None)
+            self.magic_seen.callback(self)
 
     def errReceived(self, data):
         sys.stdout.write(data)
@@ -134,7 +134,12 @@ def _run_node(reactor, node_dir, request, magic_text):
 
     # we return the 'process' ITransport instance
     # XXX abusing the Deferred; should use .when_magic_seen() or something?
-    protocol.magic_seen.addCallback(lambda _: process)
+
+    def got_proto(proto):
+        process._protocol = proto
+        process._node_dir = node_dir
+        return process
+    protocol.magic_seen.addCallback(got_proto)
     return protocol.magic_seen
 
 

src/allmydata/frontends/magic_folder.py

@@ -29,6 +29,7 @@ from allmydata.util.time_format import format_time
 from allmydata.immutable.upload import FileName, Data
 from allmydata import magicfolderdb, magicpath
 
+
 IN_EXCL_UNLINK = 0x04000000L
 
 def get_inotify_module():
@@ -422,9 +423,9 @@ class QueueMixin(HookMixin):
                 self._log("  done: %r" % proc)
             except Exception as e:
                 log.err("processing '%r' failed: %s" % (item, e))
-                proc = None  # actually in old _lazy_tail way, proc would be Failure
+                proc = Failure()
-            # XXX can we just get rid of the hooks now?
+
-            yield self._call_hook(proc, 'processed')
+            self._call_hook(proc, 'processed')
 
     def _get_relpath(self, filepath):
         self._log("_get_relpath(%r)" % (filepath,))
@@ -720,7 +721,10 @@ class Uploader(QueueMixin):
 
                 def _add_db_entry(filenode):
                     filecap = filenode.get_uri()
-                    last_downloaded_uri = metadata.get('last_downloaded_uri', None)
+                    # if we're uploading a file, we want to set
+                    # last_downloaded_uri to the filecap so that we don't
+                    # 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, new_version, filecap,
                                                 last_downloaded_uri, last_downloaded_timestamp,
                                                 pathinfo)
@@ -792,7 +796,10 @@ class Uploader(QueueMixin):
 
                 def _add_db_entry(filenode):
                     filecap = filenode.get_uri()
-                    last_downloaded_uri = metadata.get('last_downloaded_uri', None)
+                    # if we're uploading a file, we want to set
+                    # last_downloaded_uri to the filecap so that we don't
+                    # 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, new_version, filecap,
                                                 last_downloaded_uri, last_downloaded_timestamp,
                                                 pathinfo)
@@ -903,6 +910,21 @@ class WriteFileMixin(object):
         return abspath_u
 
 
+def _is_empty_filecap(client, cap):
+    """
+    Internal helper.
+
+    :param cap: a capability URI
+
+    :returns: True if "cap" represents an empty file
+    """
+    node = client.create_node_from_uri(
+        None,
+        cap.encode('ascii'),
+    )
+    return (not node.get_size())
+
+
 class DownloadItem(QueuedItem):
     """
     Represents a single item in the _deque of the Downloader
@@ -982,7 +1004,9 @@ class Downloader(QueueMixin, WriteFileMixin):
         self._log("version %r" % (db_entry.version,))
         if db_entry.version < remote_version:
             return True
-        if db_entry.last_downloaded_uri != remote_uri:
+        if db_entry.last_downloaded_uri is None and _is_empty_filecap(self._client, remote_uri):
+            pass
+        elif db_entry.last_downloaded_uri != remote_uri:
             return True
         return False
 
@@ -1144,7 +1168,8 @@ class Downloader(QueueMixin, WriteFileMixin):
         def do_update_db(written_abspath_u):
             filecap = item.file_node.get_uri()
             last_uploaded_uri = item.metadata.get('last_uploaded_uri', None)
-            self._log("DOUPDATEDB %r" % written_abspath_u)
+            if not item.file_node.get_size():
+                filecap = None  # ^ is an empty file
             last_downloaded_uri = filecap
             last_downloaded_timestamp = now
             written_pathinfo = get_pathinfo(written_abspath_u)
@@ -1178,8 +1203,9 @@ class Downloader(QueueMixin, WriteFileMixin):
             if db_entry:
                 if dmd_last_downloaded_uri is not None and db_entry.last_downloaded_uri is not None:
                     if dmd_last_downloaded_uri != db_entry.last_downloaded_uri:
-                        is_conflict = True
+                        if not _is_empty_filecap(self._client, dmd_last_downloaded_uri):
-                        self._count('objects_conflicted')
+                            is_conflict = True
+                            self._count('objects_conflicted')
                 elif dmd_last_uploaded_uri is not None and dmd_last_uploaded_uri != db_entry.last_uploaded_uri:
                     is_conflict = True
                     self._count('objects_conflicted')

src/allmydata/test/cli/test_magic_folder.py

@@ -555,6 +555,14 @@ class CreateMagicFolder(MagicFolderCLITestMixin, unittest.TestCase):
         d.addCallback(lambda ign: self.check_config(0, abs_local_dir_u))
         return d
 
+    def test_help_synopsis(self):
+        self.basedir = "cli/MagicFolder/help_synopsis"
+        os.makedirs(self.basedir)
+
+        o = magic_folder_cli.CreateOptions()
+        o.parent = magic_folder_cli.MagicFolderCommand()
+        o.parent.getSynopsis()
+
     def test_create_invite_join_failure(self):
         self.basedir = "cli/MagicFolder/create-invite-join-failure"
         os.makedirs(self.basedir)

src/allmydata/test/test_magic_folder.py

@@ -865,6 +865,8 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
             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')
@@ -881,9 +883,12 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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.failIf(os.path.exists(bob_fname))
+        self.assertFalse(os.path.exists(bob_fname))
+        self.assertTrue(os.path.exists(bob_fname + '.backup'))
+        self.assertFalse(os.path.exists(bob_fname + '.conflict'))
 
         # 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')
@@ -1080,13 +1085,13 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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))
+        d.addCallback(lambda ign: 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))
+        d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1, magic=self.alice_magicfolder))
 
         def Alice_conflicts_with_Bobs_last_downloaded_uri():
             if _debug: print "Alice conflicts with Bob\n"
@@ -1105,10 +1110,10 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
 
         d.addCallback(lambda ign: Alice_conflicts_with_Bobs_last_downloaded_uri())
         d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 4))
-        d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1))
+        d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0))
         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_downloader_count('objects_conflicted', 1, 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))
 
@@ -1124,7 +1129,7 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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_downloader_count('objects_conflicted', 1, magic=self.alice_magicfolder))
         d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 1, magic=self.bob_magicfolder))
 
         def advance(ign):
@@ -1151,13 +1156,13 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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))
-        d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1))
+        d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 0))
         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_conflicted', 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_downloaded', 2, magic=self.alice_magicfolder))
 #        d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 1, magic=self.bob_magicfolder))
@@ -1168,13 +1173,13 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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_downloader_count('objects_conflicted', 0))
         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_conflicted', 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_downloaded', 2, magic=self.alice_magicfolder))
 ##        d.addCallback(lambda ign: self._check_uploader_count('files_uploaded', 1, magic=self.bob_magicfolder))
@@ -1197,13 +1202,13 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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', 2))
+        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_conflicted', 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_downloaded', 2, magic=self.alice_magicfolder))
 
@@ -1215,8 +1220,8 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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, magic=self.alice_magicfolder))
-        d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 2))
+        d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1))
         d.addCallback(lambda ign: self._check_downloader_count('objects_downloaded', 6))
 
         # prepare to perform another conflict test
@@ -1231,8 +1236,8 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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', 2))
+        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))
+        d.addCallback(lambda ign: self._check_downloader_count('objects_conflicted', 1, magic=self.alice_magicfolder))
 
         @defer.inlineCallbacks
         def Bob_to_rewrite_file3():
@@ -1245,13 +1250,13 @@ class MagicFolderAliceBobTestMixin(MagicFolderCLITestMixin, ShouldFailMixin, Rea
         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', 2))
+        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_conflicted', 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_downloaded', 3, magic=self.alice_magicfolder))
 

src/allmydata/util/deferredutil.py

@@ -83,7 +83,7 @@ def _with_log(op, res):
     """
     try:
         op(res)
-    except defer.AlreadyCalledError, e:
+    except defer.AlreadyCalledError as e:
         log.err(e, op=repr(op), level=log.WEIRD)
 
 def eventually_callback(d):