From: david-sarah Date: Thu, 20 May 2010 00:36:52 +0000 (-0700) Subject: SFTP: improve logging so that results of requests are (usually) logged. X-Git-Tag: trac-4400~17 X-Git-Url: https://git.rkrishnan.org/components/%22news.html//%22?a=commitdiff_plain;h=7f9e351bce5f3fb7b25d83403dcb128a60ebdcff;p=tahoe-lafs%2Ftahoe-lafs.git SFTP: improve logging so that results of requests are (usually) logged. --- 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 = "" % (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, )" % (offset, len(data)), level=OPERATIONAL) + self.log(".writeChunk(%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': # - 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",