Add debug logging to FUSE flush to make upload completion clearer (#1247)

In some edge cases, Mountpoint will not be able to complete the MPU
before the file is closed. For instance, we will not complete uploads
where no bytes have been written since it can be common for applications
to fork and result in file descriptor being closed before writing
begins.

If an application relies on close completing before another system
queries S3, it could lead to a race condition where the object is not
yet in S3.

While this is an edge case, this change adds debug logging which can
help identify when this behavior occurs.

### Does this change impact existing behavior?

Logging change only.

### Does this change need a changelog entry? Does it require a version
change?

No, logging change only.

---

By submitting this pull request, I confirm that my contribution is made
under the terms of the Apache 2.0 license and I agree to the terms of
the [Developer Certificate of Origin
(DCO)](https://developercertificate.org/).

---------

Signed-off-by: Daniel Carl Jones <[email protected]>

Author: dannycjones

mountpoint-s3/src/fs.rs

@@ -850,11 +850,22 @@ where
             FileHandleState::Write(write_state) => write_state,
         };
 
-        let result = write_state.complete_if_in_progress(&file_handle.full_key).await;
+        let complete_result = write_state.complete_if_in_progress(&file_handle.full_key).await;
         metrics::gauge!("fs.current_handles", "type" => "write").decrement(1.0);
-        // Errors won't actually be seen by the user because `release` is async,
-        // but it's the right thing to do.
-        result
+
+        match complete_result {
+            Ok(upload_completed_async) => {
+                if upload_completed_async {
+                    debug!(key = ?&file_handle.full_key, "upload completed async after file was closed");
+                }
+                Ok(())
+            }
+            Err(e) => {
+                // Errors won't actually be seen by the user because `release` is async,
+                // but it's the right thing to do so we'll return it.
+                Err(e)
+            }
+        }
     }
 
     pub async fn rmdir(&self, parent_ino: InodeNo, name: &OsStr) -> Result<(), Error> {

mountpoint-s3/src/fs/handles.rs

@@ -2,7 +2,7 @@ use std::str::FromStr as _;
 
 use mountpoint_s3_client::types::ETag;
 use mountpoint_s3_client::ObjectClient;
-use tracing::{debug, error, trace};
+use tracing::{debug, error};
 
 use crate::object::ObjectId;
 use crate::prefetch::Prefetch;
@@ -295,15 +295,13 @@ where
             }
             UploadState::MPUInProgress { request, .. } => {
                 if request.size() == 0 {
-                    trace!(key, "not completing upload because nothing was written");
+                    debug!(key, "not completing upload because nothing was written yet");
                     return Ok(());
                 }
                 if !are_from_same_process(open_pid, pid) {
-                    trace!(
+                    debug!(
                         key,
-                        pid,
-                        open_pid,
-                        "not completing upload because current pid differs from pid at open"
+                        pid, open_pid, "not completing upload because current PID differs from PID at open",
                     );
                     return Ok(());
                 }
@@ -329,16 +327,25 @@ where
         result
     }
 
-    pub async fn complete_if_in_progress(self, key: &str) -> Result<(), Error> {
+    /// Check state of upload, and complete the upload if it is still in-progress.
+    ///
+    /// When successful, returns `true` where the upload was still in-progress and thus completed by this method call.
+    pub async fn complete_if_in_progress(self, key: &str) -> Result<bool, Error> {
         match self {
             UploadState::AppendInProgress {
                 request,
                 handle,
                 initial_etag,
                 ..
-            } => Self::complete_append(request, key, handle, initial_etag).await,
-            UploadState::MPUInProgress { request, handle, .. } => Self::complete_upload(request, key, handle).await,
-            UploadState::Failed(_) | UploadState::Completed => Ok(()),
+            } => {
+                Self::complete_append(request, key, handle, initial_etag).await?;
+                Ok(true)
+            }
+            UploadState::MPUInProgress { request, handle, .. } => {
+                Self::complete_upload(request, key, handle).await?;
+                Ok(true)
+            }
+            UploadState::Failed(_) | UploadState::Completed => Ok(false),
         }
     }