SftpSubsystem eats exceptions

[Thrameos]

Version

2.9.3

Bug description

While trying to implement a virtual file system for SFTPD, I ran into a condition in which the connection would close but there was nothing in the logs. After 5 hours of trying to configure the logger all I could see is DEBUG messages, but no log of the exception or error. I eventually traced it down that although there is a master catch in SftpSubsystem.run, it was never being reached. It appears that AbstractSftpSubsystemHelper contains a lot of code with this sort of pattern...

      } catch (IOException | RuntimeException e) {
            sendStatus(prepareReply(buffer), id, e, SftpConstants.SSH_FXP_OPEN, path);
            return;
        }

It seems like poor practice to not log something when an exception occurs.

To reproduce this I implemented a custom FileSystemFactory which returned MyFileSystem in which getSeparator() throw an exception. To hit multiple points I had to proxy Path, FileSystem, and FileSystemProvider to the normal versions. The exception must happen in the Path, FileSystem, or FileSystemProvider. Throws in FileSystemFactory are caught properly as SftpSubsystem catches during prepare, but not in doProcess.

Actual behavior

Nothing was logged.

Expected behavior

A log message with the source of the exception. If this is addressed, perhaps this should be logged at the DEBUG level as this was not normally logged in the past. After all there are a lot of tolerable exceptions (missing file, permissions, etc) that are not errors for normal operation.

Relevant log output

No response

Other information

Logging was configured with log4j with DEBUG to console. But the lack of output is programmatic rather than the logger, so it should be universal.

[tomaswolf]

There is debug logging in sendStatus(), but it's true that it doesn't log the exception itself or its stack trace.

Additional logging in the first variant (with the Throwable parameter) might be good indeed.

Do you want to provide a PR?

[Thrameos]

I gave it a shot. I am not sure what information is needed to identify the source. I put the session and the id assuming that it matches the other calls.