Further finetuned IO error categorization and logging

src/server/controlchan/control_loop.rs

@@ -390,6 +390,7 @@ where
                 ErrorKind::PermanentDirectoryNotEmpty => Ok(Reply::new(ReplyCode::FileError, "Directory not empty")),
                 ErrorKind::PermissionDenied => Ok(Reply::new(ReplyCode::FileError, "Permission denied")),
                 ErrorKind::CommandNotImplemented => Ok(Reply::new(ReplyCode::CommandNotImplemented, "Command not implemented")),
+                ErrorKind::ConnectionClosed => Ok(Reply::new(ReplyCode::ConnectionClosed, "Connection closed")),
             },
             CommandChannelReply(reply) => Ok(reply),
         }

src/server/datachan.rs

@@ -171,7 +171,10 @@ where
         if let Err(err) = output.shutdown().await {
             match err.kind() {
                 std::io::ErrorKind::BrokenPipe => {
-                    slog::debug!(self.logger, "Output stream was already shutdown after RETR: {:?}", err);
+                    slog::debug!(self.logger, "Output stream was already closed by peer after RETR: {:?}", err);
+                }
+                std::io::ErrorKind::NotConnected => {
+                    slog::debug!(self.logger, "Output stream was already closed after RETR: {:?}", err);
                 }
                 _ => slog::warn!(self.logger, "Could not shutdown output stream after RETR: {:?}", err),
             }
@@ -201,9 +204,26 @@ where
                 }
             }
             Err(err) => {
-                slog::warn!(self.logger, "Error during RETR transfer after {}: {:?}", HumanDuration(duration), err);
+                let io_error_kind = err.get_io_error().map(|e| e.kind());
+
+                if io_error_kind == Some(std::io::ErrorKind::BrokenPipe) {
+                    slog::info!(
+                        self.logger,
+                        "RETR transfer interrupted by client (BrokenPipe). This could be expected client behavior. Path {:?}; Duration {} (number of bytes copied unknown)",
+                        &path_copy,
+                        HumanDuration(duration)
+                    );
+                } else {
+                    slog::warn!(
+                        self.logger,
+                        "Error during RETR {:?} transfer after {}: {:?}",
+                        &path_copy,
+                        HumanDuration(duration),
+                        err
+                    );
+                }
 
-                categorize_and_register_error(&err, "retr");
+                categorize_and_register_error(&self.logger, &err, "retr");
 
                 if let Err(err) = tx.send(ControlChanMsg::StorageError(err)).await {
                     slog::warn!(self.logger, "Could not notify control channel of error with RETR: {:?}", err);
@@ -248,7 +268,7 @@ where
             Err(err) => {
                 slog::warn!(self.logger, "Error during STOR transfer after {}: {:?}", HumanDuration(duration), err);
 
-                categorize_and_register_error(&err, "stor");
+                categorize_and_register_error(&self.logger, &err, "stor");
 
                 if let Err(err) = tx.send(ControlChanMsg::StorageError(err)).await {
                     slog::error!(self.logger, "Could not notify control channel of error with STOR: {:?}", err);
@@ -283,7 +303,10 @@ where
                 if let Err(err) = output.shutdown().await {
                     match err.kind() {
                         std::io::ErrorKind::BrokenPipe => {
-                            slog::debug!(self.logger, "Output stream was already shutdown after {}: {:?}", command.as_str(), err);
+                            slog::debug!(self.logger, "Output stream was already closed by peer after {}: {:?}", command.as_str(), err);
+                        }
+                        std::io::ErrorKind::NotConnected => {
+                            slog::debug!(self.logger, "Output stream was already closed after {}: {:?}", command.as_str(), err);
                         }
                         _ => slog::warn!(self.logger, "Could not shutdown output stream after {}: {:?}", command.as_str(), err),
                     }
@@ -317,7 +340,7 @@ where
                         );
 
                         let err = Error::from(e);
-                        categorize_and_register_error(&err, command.as_lower_str());
+                        categorize_and_register_error(&self.logger, &err, command.as_lower_str());
                     }
                 }
             }
@@ -333,7 +356,7 @@ where
                     err,
                 );
 
-                categorize_and_register_error(&err, command.as_lower_str());
+                categorize_and_register_error(&self.logger, &err, command.as_lower_str());
 
                 if let Err(err) = tx.send(ControlChanMsg::StorageError(err)).await {
                     slog::error!(self.logger, "Could not notify control channel of error with {}: {:?}", command.as_str(), err);
@@ -560,12 +583,33 @@ impl fmt::Display for TransferSpeed {
 // Collapse the StorageError kind into a client-error, server-error or unknown-error.
 // The PermissionDenied is seperated because it depends on specifics whether it is a server or client error
 // Unknown errors should not happen but need to be handled
-fn categorize_and_register_error(err: &Error, command: &'static str) {
+fn categorize_and_register_error(logger: &slog::Logger, err: &Error, command: &'static str) {
     match err.kind() {
-        e if e == ErrorKind::PermanentFileNotAvailable => metrics::inc_transferred(command, "client-error"),
-        e if e == ErrorKind::TransientFileNotAvailable || e == ErrorKind::LocalError => metrics::inc_transferred(command, "server-error"),
-        e if e == ErrorKind::PermissionDenied => metrics::inc_transferred(command, "permission-error"),
-        _ => metrics::inc_transferred(command, "unknown-error"),
+        ErrorKind::PermanentFileNotAvailable => metrics::inc_transferred(command, "client-error"),
+        ErrorKind::TransientFileNotAvailable | ErrorKind::LocalError => metrics::inc_transferred(command, "server-error"),
+        ErrorKind::PermissionDenied => metrics::inc_transferred(command, "permission-error"),
+        ErrorKind::ConnectionClosed => {
+            if let Some(io_error) = err.get_io_error() {
+                match io_error.kind() {
+                    std::io::ErrorKind::ConnectionReset => metrics::inc_transferred(command, "network-error"), // Could also be a client error, but can't be sure
+                    std::io::ErrorKind::BrokenPipe => {
+                        // Clients like Cyberduck appear to close the connection prematurely for chunked downloading, generating many "errors"
+                        if command != "retr" {
+                            metrics::inc_transferred(command, "client");
+                        }
+                    }
+                    std::io::ErrorKind::ConnectionAborted => metrics::inc_transferred(command, "server-error"), // Could be a network issue
+                    _ => {
+                        slog::debug!(logger, "Unmapped ConnectionClosed io error: {:?}", io_error);
+                        metrics::inc_transferred(command, "server-error")
+                    }
+                }
+            }
+        }
+        _ => {
+            slog::debug!(logger, "Unmapped error: {:?}", err);
+            metrics::inc_transferred(command, "unknown-error")
+        }
     }
 }
 

src/storage/error.rs

@@ -29,6 +29,11 @@ impl Error {
     pub fn kind(&self) -> ErrorKind {
         self.kind
     }
+
+    /// Attempts to get a reference to the inner `std::io::Error` if there is one.
+    pub fn get_io_error(&self) -> Option<&std::io::Error> {
+        self.source.as_ref()?.downcast_ref::<std::io::Error>()
+    }
 }
 
 impl From<ErrorKind> for Error {
@@ -67,7 +72,11 @@ pub enum ErrorKind {
     /// make sense for it to be retried. For example in the case where file access is denied.
     #[display(fmt = "550 Permission denied")]
     PermissionDenied,
-    /// Error that will cause an FTP reply code of 451 to be returned to the FTP client. Its means
+    /// Error that will cause an FTP reply code of 426 to be returned to the FTP client. It means the transfer was
+    /// aborted, possibly by the client or because of a network issue
+    #[display(fmt = "426 Connection closed transfer aborted")]
+    ConnectionClosed,
+    /// Error that will cause an FTP reply code of 451 to be returned to the FTP client. It means
     /// the requested action was aborted due to a local error (internal storage back-end error) in
     /// processing.
     #[display(fmt = "451 Local error")]

src/storage/storage_backend.rs

@@ -302,37 +302,40 @@ pub trait StorageBackend<User: UserDetail>: Send + Sync + Debug {
 // The rest is assumed to be 'retryable' so they map to 4xx FTP reply, in this case a LocalError
 impl From<std::io::Error> for Error {
     fn from(err: std::io::Error) -> Self {
-        match err {
-            e if e.kind() == std::io::ErrorKind::NotFound => Error::from(ErrorKind::PermanentFileNotAvailable),
+        let kind = err.kind();
+        let raw_os_error = err.raw_os_error();
+        match (kind, raw_os_error) {
+            (std::io::ErrorKind::NotFound, _) => Error::new(ErrorKind::PermanentFileNotAvailable, err),
             // Could also be a directory, but we don't know
-            e if e.kind() == std::io::ErrorKind::AlreadyExists => Error::from(ErrorKind::PermanentFileNotAvailable),
-            e if e.kind() == std::io::ErrorKind::PermissionDenied => Error::from(ErrorKind::PermissionDenied),
+            (std::io::ErrorKind::AlreadyExists, _) => Error::new(ErrorKind::PermanentFileNotAvailable, err),
+            (std::io::ErrorKind::PermissionDenied, _) => Error::new(ErrorKind::PermissionDenied, err),
             // The below should be changed when the io_error_more issues are resolved (https://github.com/rust-lang/rust/issues/86442)
             // For each workaround, I mention the ErrorKind that can can replace it when stable
             // TODO: find a workaround for Windows
             // DirectoryNotEmpty
             #[cfg(unix)]
-            e if e.raw_os_error() == Some(libc::ENOTEMPTY) => Error::from(ErrorKind::PermanentDirectoryNotEmpty),
+            (_, Some(libc::ENOTEMPTY)) => Error::new(ErrorKind::PermanentDirectoryNotEmpty, err),
             // NotADirectory
             #[cfg(unix)]
-            e if e.raw_os_error() == Some(libc::ENOTDIR) => Error::from(ErrorKind::PermanentDirectoryNotAvailable),
+            (_, Some(libc::ENOTDIR)) => Error::new(ErrorKind::PermanentDirectoryNotAvailable, err),
             // IsADirectory, FileTooLarge, NotSeekable, InvalidFilename, FilesystemLoop
             #[cfg(unix)]
-            e if e.raw_os_error() == Some(libc::EISDIR)
-                || e.raw_os_error() == Some(libc::EFBIG)
-                || e.raw_os_error() == Some(libc::ESPIPE)
-                || e.raw_os_error() == Some(libc::ENAMETOOLONG)
-                || e.raw_os_error() == Some(libc::ELOOP) =>
-            {
-                Error::from(ErrorKind::PermanentFileNotAvailable)
+            (_, Some(libc::EISDIR) | Some(libc::EFBIG) | Some(libc::ESPIPE) | Some(libc::ENAMETOOLONG) | Some(libc::ELOOP)) => {
+                Error::new(ErrorKind::PermanentFileNotAvailable, err)
             }
             // StorageFull
             #[cfg(unix)]
-            e if e.raw_os_error() == Some(libc::ENOSPC) => Error::from(ErrorKind::InsufficientStorageSpaceError),
+            (_, Some(libc::ENOSPC)) => Error::new(ErrorKind::InsufficientStorageSpaceError, err),
             // ReadOnlyFilesystem - Read-only filesystem can be considered a permission error
             #[cfg(unix)]
-            e if e.raw_os_error() == Some(libc::EROFS) => Error::from(ErrorKind::PermissionDenied),
-            // All other errors should be retryable
+            (_, Some(libc::EROFS)) => Error::new(ErrorKind::PermissionDenied, err),
+            // Retryable error: Client most likely forcefully aborted the connection or there was a network issue
+            (std::io::ErrorKind::ConnectionReset, _) => Error::new(ErrorKind::ConnectionClosed, err),
+            // Retryable error: Client most likely intentionally closed the connection
+            (std::io::ErrorKind::BrokenPipe, _) => Error::new(ErrorKind::ConnectionClosed, err),
+            // Retryable error: There was likely a network issue
+            (std::io::ErrorKind::ConnectionAborted, _) => Error::new(ErrorKind::ConnectionClosed, err),
+            // Other errors are assumed to be local transient problems, retryable for the client
             _ => Error::new(ErrorKind::LocalError, err),
         }
     }