From 7f9e351bce5f3fb7b25d83403dcb128a60ebdcff Mon Sep 17 00:00:00 2001
From: david-sarah <david-sarah@jacaranda.org>
Date: Wed, 19 May 2010 17:36:52 -0700
Subject: [PATCH] SFTP: improve logging so that results of requests are
 (usually) logged.

---
 src/allmydata/frontends/sftpd.py | 128 ++++++++++++++++++++-----------
 src/allmydata/test/test_sftp.py  |  42 +++++-----
 2 files changed, 103 insertions(+), 67 deletions(-)

diff --git a/src/allmydata/frontends/sftpd.py b/src/allmydata/frontends/sftpd.py
index 70cd8595..fc2624f8 100644
--- a/src/allmydata/frontends/sftpd.py
+++ b/src/allmydata/frontends/sftpd.py
@@ -17,6 +17,7 @@ from twisted.conch.avatar import ConchUser
 from twisted.conch.openssh_compat import primes
 from twisted.cred import portal
 from twisted.internet.error import ProcessDone, ProcessTerminated
+from twisted.python.failure import Failure
 from twisted.internet.interfaces import ITransport
 
 from twisted.internet import defer
@@ -93,10 +94,15 @@ else:
         return lambda err: eventually(d.errback, err)
 
 
-def _raise_error(err):
-    if err is None:
-        return None
-    if noisy: logmsg("RAISE %r" % (err,), level=NOISY)
+def _convert_error(res, request):
+    if not isinstance(res, Failure):
+        logged_res = res
+        if isinstance(res, str): logged_res = "<data of length %r>" % (len(res),)
+        logmsg("SUCCESS %r %r" % (request, logged_res,), level=OPERATIONAL)
+        return res
+
+    err = res
+    logmsg("RAISE %r %r" % (request, err,), level=OPERATIONAL)
     if noisy and not use_foolscap_logging: traceback.print_exc(err)
 
     # The message argument to SFTPError must not reveal information that
@@ -125,7 +131,7 @@ def _raise_error(err):
     if err.check(EOFError):
         raise SFTPError(FX_EOF, "end of file reached")
     if err.check(defer.FirstError):
-        _raise_error(err.value.subFailure)
+        _convert_error(err.value.subFailure, request)
 
     # We assume that the error message is not anonymity-sensitive.
     raise SFTPError(FX_FAILURE, str(err.value))
@@ -572,7 +578,8 @@ class ShortReadOnlySFTPFile(PrefixingLogMixin):
         self.closed = False
 
     def readChunk(self, offset, length):
-        self.log(".readChunk(%r, %r)" % (offset, length), level=OPERATIONAL)
+        request = ".readChunk(%r, %r)" % (offset, length)
+        self.log(request, level=OPERATIONAL)
 
         if self.closed:
             def _closed(): raise SFTPError(FX_BAD_MESSAGE, "cannot read from a closed file handle")
@@ -597,10 +604,11 @@ class ShortReadOnlySFTPFile(PrefixingLogMixin):
                 eventually_callback(d)(data[offset:min(offset+length, len(data))])
             return data
         self.async.addCallbacks(_read, eventually_errback(d))
+        d.addBoth(_convert_error, request)
         return d
 
     def writeChunk(self, offset, data):
-        self.log(".writeChunk(%r, <data of length %r>)" % (offset, len(data)), level=OPERATIONAL)
+        self.log(".writeChunk(%r, <data of length %r>) denied" % (offset, len(data)), level=OPERATIONAL)
 
         def _denied(): raise SFTPError(FX_PERMISSION_DENIED, "file handle was not opened for writing")
         return defer.execute(_denied)
@@ -612,16 +620,19 @@ class ShortReadOnlySFTPFile(PrefixingLogMixin):
         return defer.succeed(None)
 
     def getAttrs(self):
-        self.log(".getAttrs()", level=OPERATIONAL)
+        request = ".getAttrs()"
+        self.log(request, level=OPERATIONAL)
 
         if self.closed:
             def _closed(): raise SFTPError(FX_BAD_MESSAGE, "cannot get attributes for a closed file handle")
             return defer.execute(_closed)
 
-        return defer.succeed(_populate_attrs(self.filenode, self.metadata))
+        d = defer.execute(_populate_attrs, self.filenode, self.metadata)
+        d.addBoth(_convert_error, request)
+        return d
 
     def setAttrs(self, attrs):
-        self.log(".setAttrs(%r)" % (attrs,), level=OPERATIONAL)
+        self.log(".setAttrs(%r) denied" % (attrs,), level=OPERATIONAL)
         def _denied(): raise SFTPError(FX_PERMISSION_DENIED, "file handle was not opened for writing")
         return defer.execute(_denied)
 
@@ -680,8 +691,11 @@ class GeneralSFTPFile(PrefixingLogMixin):
                     filenode.read(self.consumer, 0, None)
                 self.async.addCallback(_read)
 
+        if noisy: logmsg("__init__ done", level=NOISY)
+
     def readChunk(self, offset, length):
-        self.log(".readChunk(%r, %r)" % (offset, length), level=OPERATIONAL)
+        request = ".readChunk(%r, %r)" % (offset, length)
+        self.log(request, level=OPERATIONAL)
 
         if not (self.flags & FXF_READ):
             def _denied(): raise SFTPError(FX_PERMISSION_DENIED, "file handle was not opened for reading")
@@ -695,11 +709,12 @@ class GeneralSFTPFile(PrefixingLogMixin):
         def _read(ign):
             if noisy: self.log("_read in readChunk(%r, %r)" % (offset, length), level=NOISY)
             d2 = self.consumer.read(offset, length)
-            d2.addErrback(_raise_error)
+            d2.addErrback(_convert_error, request)
             d2.addCallbacks(eventually_callback(d), eventually_errback(d))
             # It is correct to drop d2 here.
             return None
         self.async.addCallbacks(_read, eventually_errback(d))
+        d.addBoth(_convert_error, request)
         return d
 
     def writeChunk(self, offset, data):
@@ -731,13 +746,15 @@ class GeneralSFTPFile(PrefixingLogMixin):
                 write_offset = self.consumer.get_current_size()
 
             self.consumer.overwrite(write_offset, data)
+            if noisy: self.log("overwrite done", level=NOISY)
             return None
         self.async.addCallback(_write)
         # don't addErrback to self.async, just allow subsequent async ops to fail.
         return defer.succeed(None)
 
     def close(self):
-        self.log(".close()", level=OPERATIONAL)
+        request = ".close()"
+        self.log(request, level=OPERATIONAL)
 
         if self.closed:
             return defer.succeed(None)
@@ -771,10 +788,12 @@ class GeneralSFTPFile(PrefixingLogMixin):
 
         d = defer.Deferred()
         self.async.addCallbacks(eventually_callback(d), eventually_errback(d))
+        d.addBoth(_convert_error, request)
         return d
 
     def getAttrs(self):
-        self.log(".getAttrs()", level=OPERATIONAL)
+        request = ".getAttrs()"
+        self.log(request, level=OPERATIONAL)
 
         if self.closed:
             def _closed(): raise SFTPError(FX_BAD_MESSAGE, "cannot get attributes for a closed file handle")
@@ -791,10 +810,12 @@ class GeneralSFTPFile(PrefixingLogMixin):
             eventually_callback(d)(attrs)
             return None
         self.async.addCallbacks(_get, eventually_errback(d))
+        d.addBoth(_convert_error, request)
         return d
 
     def setAttrs(self, attrs):
-        self.log(".setAttrs(attrs) %r" % (attrs,), level=OPERATIONAL)
+        request = ".setAttrs(attrs) %r" % (attrs,)
+        self.log(request, level=OPERATIONAL)
 
         if not (self.flags & FXF_WRITE):
             def _denied(): raise SFTPError(FX_PERMISSION_DENIED, "file handle was not opened for writing")
@@ -818,6 +839,7 @@ class GeneralSFTPFile(PrefixingLogMixin):
             eventually_callback(d)(None)
             return None
         self.async.addCallbacks(_resize, eventually_errback(d))
+        d.addBoth(_convert_error, request)
         return d
 
 
@@ -863,7 +885,8 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
         return {}
 
     def openFile(self, pathstring, flags, attrs):
-        self.log(".openFile(%r, %r = %r, %r)" % (pathstring, flags, _repr_flags(flags), attrs), level=OPERATIONAL)
+        request = ".openFile(%r, %r = %r, %r)" % (pathstring, flags, _repr_flags(flags), attrs)
+        self.log(request, level=OPERATIONAL)
 
         # This is used for both reading and writing.
         # First exclude invalid combinations of flags.
@@ -910,7 +933,7 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
         # the open call; later operations would fail even if we did not make these checks.
 
         d = self._get_root(path)
-        def _got_root((root, path)):
+        def _got_root( (root, path) ):
             if root.is_unknown():
                 raise SFTPError(FX_PERMISSION_DENIED,
                                 "cannot open an unknown cap (or child of an unknown directory). "
@@ -1012,17 +1035,12 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
                 d2.addCallback(_got_parent)
                 return d2
         d.addCallback(_got_root)
-        d.addErrback(_raise_error)
+        d.addBoth(_convert_error, request)
         return d
 
-    def removeFile(self, pathstring):
-        self.log(".removeFile(%r)" % (pathstring,), level=OPERATIONAL)
-
-        path = self._path_from_string(pathstring)
-        return self._remove_object(path, must_be_file=True)
-
     def renameFile(self, oldpathstring, newpathstring):
-        self.log(".renameFile(%r, %r)" % (oldpathstring, newpathstring), level=OPERATIONAL)
+        request = ".renameFile(%r, %r)" % (oldpathstring, newpathstring)
+        self.log(request, level=OPERATIONAL)
 
         fromPath = self._path_from_string(oldpathstring)
         toPath = self._path_from_string(newpathstring)
@@ -1050,26 +1068,28 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
             #                              toPath[-1], overwrite=False)
             return d
         d.addCallback(_got)
-        d.addErrback(_raise_error)
+        d.addBoth(_convert_error, request)
         return d
 
     def makeDirectory(self, pathstring, attrs):
-        self.log(".makeDirectory(%r, %r)" % (pathstring, attrs), level=OPERATIONAL)
+        request = ".makeDirectory(%r, %r)" % (pathstring, attrs)
+        self.log(request, level=OPERATIONAL)
 
         path = self._path_from_string(pathstring)
         metadata = self._attrs_to_metadata(attrs)
         d = self._get_root(path)
         d.addCallback(lambda (root, path):
                       self._get_or_create_directories(root, path, metadata))
-        d.addErrback(_raise_error)
+        d.addBoth(_convert_error, request)
         return d
 
     def _get_or_create_directories(self, node, path, metadata):
         if not IDirectoryNode.providedBy(node):
             # TODO: provide the name of the blocking file in the error message.
-            raise SFTPError(FX_FAILURE,
-                            "cannot create directory because there "
-                            "is a file in the way") # close enough
+            def _blocked(): raise SFTPError(FX_FAILURE, "cannot create directory because there "
+                                                        "is a file in the way") # close enough
+            return defer.execute(_blocked)
+
         if not path:
             return defer.succeed(node)
         d = node.get(path[0])
@@ -1078,14 +1098,25 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
             return node.create_subdirectory(path[0])
         d.addErrback(_maybe_create)
         d.addCallback(self._get_or_create_directories, path[1:], metadata)
-        d.addErrback(_raise_error)
+        return d
+
+    def removeFile(self, pathstring):
+        request = ".removeFile(%r)" % (pathstring,)
+        self.log(request, level=OPERATIONAL)
+
+        path = self._path_from_string(pathstring)
+        d = self._remove_object(path, must_be_file=True)
+        d.addBoth(_convert_error, request)
         return d
 
     def removeDirectory(self, pathstring):
-        self.log(".removeDirectory(%r)" % (pathstring,), level=OPERATIONAL)
+        request = ".removeDirectory(%r)" % (pathstring,)
+        self.log(request, level=OPERATIONAL)
 
         path = self._path_from_string(pathstring)
-        return self._remove_object(path, must_be_directory=True)
+        d = self._remove_object(path, must_be_directory=True)
+        d.addBoth(_convert_error, request)
+        return d
 
     def _remove_object(self, path, must_be_directory=False, must_be_file=False):
         d = defer.maybeDeferred(self._get_parent_or_node, path)
@@ -1108,11 +1139,11 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
             d2.addCallback(_got_child)
             return d2
         d.addCallback(_got_parent)
-        d.addErrback(_raise_error)
         return d
 
     def openDirectory(self, pathstring):
-        self.log(".openDirectory(%r)" % (pathstring,), level=OPERATIONAL)
+        request = ".openDirectory(%r)" % (pathstring,)
+        self.log(request, level=OPERATIONAL)
 
         path = self._path_from_string(pathstring)
         d = self._get_node_and_metadata_for_path(path)
@@ -1140,11 +1171,12 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
             d2.addCallback(_render)
             return d2
         d.addCallback(_list)
-        d.addErrback(_raise_error)
+        d.addBoth(_convert_error, request)
         return d
 
     def getAttrs(self, pathstring, followLinks):
-        self.log(".getAttrs(%r, followLinks=%r)" % (pathstring, followLinks), level=OPERATIONAL)
+        request = ".getAttrs(%r, followLinks=%r)" % (pathstring, followLinks)
+        self.log(request, level=OPERATIONAL)
 
         d = self._get_node_and_metadata_for_path(self._path_from_string(pathstring))
         def _render( (node, metadata) ):
@@ -1157,7 +1189,7 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
             d2.addCallback(lambda size: _populate_attrs(node, metadata, size=size))
             return d2
         d.addCallback(_render)
-        d.addErrback(_raise_error)
+        d.addBoth(_convert_error, request)
         return d
 
     def setAttrs(self, pathstring, attrs):
@@ -1166,25 +1198,28 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
         if "size" in attrs:
             # this would require us to download and re-upload the truncated/extended
             # file contents
-            raise SFTPError(FX_OP_UNSUPPORTED, "setAttrs wth size attribute")
-        return None
+            def _unsupported(): raise SFTPError(FX_OP_UNSUPPORTED, "setAttrs wth size attribute")
+            return defer.execute(_unsupported)
+        return defer.succeed(None)
 
     def readLink(self, pathstring):
         self.log(".readLink(%r)" % (pathstring,), level=OPERATIONAL)
 
-        raise SFTPError(FX_OP_UNSUPPORTED, "readLink")
+        def _unsupported(): raise SFTPError(FX_OP_UNSUPPORTED, "readLink")
+        return defer.execute(_unsupported)
 
     def makeLink(self, linkPathstring, targetPathstring):
         self.log(".makeLink(%r, %r)" % (linkPathstring, targetPathstring), level=OPERATIONAL)
 
-        raise SFTPError(FX_OP_UNSUPPORTED, "makeLink")
+        def _unsupported(): raise SFTPError(FX_OP_UNSUPPORTED, "makeLink")
+        return defer.execute(_unsupported)
 
     def extendedRequest(self, extendedName, extendedData):
         self.log(".extendedRequest(%r, %r)" % (extendedName, extendedData), level=OPERATIONAL)
 
         if extendedName == 'statvfs@openssh.com' or extendedName == 'fstatvfs@openssh.com':
             # <http://dev.libssh.org/ticket/11>
-            return struct.pack('>11Q',
+            return defer.succeed(struct.pack('>11Q',
                 1024,         # uint64  f_bsize     /* file system block size */
                 1024,         # uint64  f_frsize    /* fundamental fs block size */
                 628318530,    # uint64  f_blocks    /* number of blocks (unit f_frsize) */
@@ -1196,9 +1231,10 @@ class SFTPUserHandler(ConchUser, PrefixingLogMixin):
                 0x1AF5,       # uint64  f_fsid      /* file system id */
                 2,            # uint64  f_flag      /* bit mask = ST_NOSUID; not ST_RDONLY */
                 65535,        # uint64  f_namemax   /* maximum filename length */
-                )
+                ))
 
-        raise SFTPError(FX_OP_UNSUPPORTED, "extendedRequest %r" % extendedName)
+        def _unsupported(): raise SFTPError(FX_OP_UNSUPPORTED, "extendedRequest %r" % extendedName)
+        return defer.execute(_unsupported)
 
     def realPath(self, pathstring):
         self.log(".realPath(%r)" % (pathstring,), level=OPERATIONAL)
diff --git a/src/allmydata/test/test_sftp.py b/src/allmydata/test/test_sftp.py
index 609e8fcd..2f1a7ebe 100644
--- a/src/allmydata/test/test_sftp.py
+++ b/src/allmydata/test/test_sftp.py
@@ -223,35 +223,35 @@ class Handler(GridTestMixin, ShouldFailMixin, unittest.TestCase):
 
         return d
 
-    def test_raise_error(self):
-        self.failUnlessReallyEqual(sftpd._raise_error(None), None)
+    def test_convert_error(self):
+        self.failUnlessReallyEqual(sftpd._convert_error(None, "request"), None)
         
         d = defer.succeed(None)
         d.addCallback(lambda ign:
-            self.shouldFailWithSFTPError(sftp.FX_FAILURE, "_raise_error SFTPError",
-                                         sftpd._raise_error, Failure(sftp.SFTPError(sftp.FX_FAILURE, "foo"))))
+            self.shouldFailWithSFTPError(sftp.FX_FAILURE, "_convert_error SFTPError",
+                                         sftpd._convert_error, Failure(sftp.SFTPError(sftp.FX_FAILURE, "foo")), "request"))
         d.addCallback(lambda ign:
-            self.shouldFailWithSFTPError(sftp.FX_NO_SUCH_FILE, "_raise_error NoSuchChildError",
-                                         sftpd._raise_error, Failure(NoSuchChildError("foo"))))
+            self.shouldFailWithSFTPError(sftp.FX_NO_SUCH_FILE, "_convert_error NoSuchChildError",
+                                         sftpd._convert_error, Failure(NoSuchChildError("foo")), "request"))
         d.addCallback(lambda ign:
-            self.shouldFailWithSFTPError(sftp.FX_FAILURE, "_raise_error ExistingChildError",
-                                         sftpd._raise_error, Failure(ExistingChildError("foo"))))
+            self.shouldFailWithSFTPError(sftp.FX_FAILURE, "_convert_error ExistingChildError",
+                                         sftpd._convert_error, Failure(ExistingChildError("foo")), "request"))
         d.addCallback(lambda ign:
-            self.shouldFailWithSFTPError(sftp.FX_PERMISSION_DENIED, "_raise_error NotWriteableError",
-                                         sftpd._raise_error, Failure(NotWriteableError("foo"))))
+            self.shouldFailWithSFTPError(sftp.FX_PERMISSION_DENIED, "_convert_error NotWriteableError",
+                                         sftpd._convert_error, Failure(NotWriteableError("foo")), "request"))
         d.addCallback(lambda ign:
-            self.shouldFailWithSFTPError(sftp.FX_OP_UNSUPPORTED, "_raise_error NotImplementedError",
-                                         sftpd._raise_error, Failure(NotImplementedError("foo"))))
+            self.shouldFailWithSFTPError(sftp.FX_OP_UNSUPPORTED, "_convert_error NotImplementedError",
+                                         sftpd._convert_error, Failure(NotImplementedError("foo")), "request"))
         d.addCallback(lambda ign:
-            self.shouldFailWithSFTPError(sftp.FX_EOF, "_raise_error EOFError",
-                                         sftpd._raise_error, Failure(EOFError("foo"))))
+            self.shouldFailWithSFTPError(sftp.FX_EOF, "_convert_error EOFError",
+                                         sftpd._convert_error, Failure(EOFError("foo")), "request"))
         d.addCallback(lambda ign:
-            self.shouldFailWithSFTPError(sftp.FX_EOF, "_raise_error defer.FirstError",
-                                         sftpd._raise_error, Failure(defer.FirstError(
-                                                               Failure(sftp.SFTPError(sftp.FX_EOF, "foo")), 0))))
+            self.shouldFailWithSFTPError(sftp.FX_EOF, "_convert_error defer.FirstError",
+                                         sftpd._convert_error, Failure(defer.FirstError(
+                                                                 Failure(sftp.SFTPError(sftp.FX_EOF, "foo")), 0)), "request"))
         d.addCallback(lambda ign:
-            self.shouldFailWithSFTPError(sftp.FX_FAILURE, "_raise_error AssertionError",
-                                         sftpd._raise_error, Failure(AssertionError("foo"))))
+            self.shouldFailWithSFTPError(sftp.FX_FAILURE, "_convert_error AssertionError",
+                                         sftpd._convert_error, Failure(AssertionError("foo")), "request"))
 
         return d
 
@@ -339,8 +339,8 @@ class Handler(GridTestMixin, ShouldFailMixin, unittest.TestCase):
             self.failUnlessReallyEqual(attrs['size'], 10, repr(attrs))
         d.addCallback(_check_attrs)
 
-        d.addCallback(lambda ign:
-            self.failUnlessReallyEqual(self.handler.setAttrs("small", {}), None))
+        d.addCallback(lambda ign: self.handler.setAttrs("small", {}))
+        d.addCallback(lambda res: self.failUnlessReallyEqual(res, None))
 
         d.addCallback(lambda ign:
             self.shouldFailWithSFTPError(sftp.FX_OP_UNSUPPORTED, "setAttrs size",
-- 
2.45.2