diff --git a/mountpoint-s3/src/fs.rs b/mountpoint-s3/src/fs.rs index 91ed2ab13..4b7ea07ed 100644 --- a/mountpoint-s3/src/fs.rs +++ b/mountpoint-s3/src/fs.rs @@ -15,6 +15,7 @@ use mountpoint_s3_client::types::ETag; use mountpoint_s3_client::ObjectClient; use crate::inode::{Inode, InodeError, InodeKind, LookedUp, ReaddirHandle, Superblock, SuperblockConfig, WriteHandle}; +use crate::logging; use crate::prefetch::{Prefetch, PrefetchReadError, PrefetchResult}; use crate::prefix::Prefix; use crate::sync::atomic::{AtomicI64, AtomicU64, Ordering}; @@ -167,7 +168,7 @@ impl UploadState { UploadState::InProgress { handle, .. } => { if let Err(err) = handle.finish_writing() { // Log the issue but still return the write error. - error!(?err, "error updating the inode status"); + error!(?err, ?key, "error updating the inode status"); } } Self::Failed(_) | Self::Completed => unreachable!("checked above"), @@ -231,7 +232,7 @@ impl UploadState { }; if let Err(err) = handle.finish_writing() { // Log the issue but still return put_result. - error!(?err, "error updating the inode status"); + error!(?err, ?key, "error updating the inode status"); } put_result } @@ -666,6 +667,7 @@ where None => return reply.error(err!(libc::EBADF, "invalid file handle")), } }; + logging::record_name(handle.inode.name()); let file_etag: ETag; let mut request = match &handle.typ { FileHandleType::Write { .. } => return reply.error(err!(libc::EBADF, "file handle is not open for reads")), @@ -770,6 +772,7 @@ where None => return Err(err!(libc::EBADF, "invalid file handle")), } }; + logging::record_name(handle.inode.name()); let len = { let mut request = match &handle.typ { @@ -971,6 +974,7 @@ where None => return Err(err!(libc::EBADF, "invalid file handle")), } }; + logging::record_name(file_handle.inode.name()); let mut request = match &file_handle.typ { FileHandleType::Write(request) => request.lock().await, FileHandleType::Read { .. } => return Ok(()), @@ -1019,6 +1023,7 @@ where .remove(&fh) .ok_or_else(|| err!(libc::EBADF, "invalid file handle"))? }; + logging::record_name(file_handle.inode.name()); // Unwrap the atomic reference to have full ownership. // The kernel should make a release call when there is no more references to the file handle, diff --git a/mountpoint-s3/src/fs/error.rs b/mountpoint-s3/src/fs/error.rs index 73fd10643..c0d79d6d0 100644 --- a/mountpoint-s3/src/fs/error.rs +++ b/mountpoint-s3/src/fs/error.rs @@ -111,7 +111,7 @@ impl ToErrno for InodeError { fn to_errno(&self) -> libc::c_int { match self { InodeError::ClientError(_) => libc::EIO, - InodeError::FileDoesNotExist => libc::ENOENT, + InodeError::FileDoesNotExist(_, _) => libc::ENOENT, InodeError::InodeDoesNotExist(_) => libc::ENOENT, InodeError::InvalidFileName(_) => libc::EINVAL, InodeError::NotADirectory(_) => libc::ENOTDIR, diff --git a/mountpoint-s3/src/fuse.rs b/mountpoint-s3/src/fuse.rs index 324e32e75..06f09a09e 100644 --- a/mountpoint-s3/src/fuse.rs +++ b/mountpoint-s3/src/fuse.rs @@ -6,7 +6,7 @@ use std::ffi::OsStr; use std::path::Path; use std::time::SystemTime; use time::OffsetDateTime; -use tracing::{instrument, Instrument}; +use tracing::{field, instrument, Instrument}; use crate::fs::{ self, DirectoryEntry, DirectoryReplier, InodeNo, ReadReplier, S3Filesystem, S3FilesystemConfig, ToErrno, @@ -92,7 +92,7 @@ where } } - #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino))] + #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, name=field::Empty))] fn getattr(&self, _req: &Request<'_>, ino: InodeNo, reply: ReplyAttr) { match block_on(self.fs.getattr(ino).in_current_span()) { Ok(attr) => reply.attr(&attr.ttl, &attr.attr), @@ -100,12 +100,12 @@ where } } - #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino, nlookup))] + #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino, nlookup, name=field::Empty))] fn forget(&self, _req: &Request<'_>, ino: u64, nlookup: u64) { block_on(self.fs.forget(ino, nlookup)); } - #[instrument(level="warn", skip_all, fields(req=req.unique(), ino=ino, pid=req.pid()))] + #[instrument(level="warn", skip_all, fields(req=req.unique(), ino=ino, pid=req.pid(), name=field::Empty))] fn open(&self, req: &Request<'_>, ino: InodeNo, flags: i32, reply: ReplyOpen) { match block_on(self.fs.open(ino, flags, req.pid()).in_current_span()) { Ok(opened) => reply.opened(opened.fh, opened.flags), @@ -113,7 +113,7 @@ where } } - #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, fh=fh, offset=offset, size=size))] + #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, fh=fh, offset=offset, size=size, name=field::Empty))] fn read( &self, _req: &Request<'_>, @@ -164,7 +164,7 @@ where metrics::histogram!("fuse.io_size", bytes_sent as f64, "type" => "read"); } - #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=parent))] + #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=parent, name=field::Empty))] fn opendir(&self, _req: &Request<'_>, parent: InodeNo, flags: i32, reply: ReplyOpen) { match block_on(self.fs.opendir(parent, flags).in_current_span()) { Ok(opened) => reply.opened(opened.fh, opened.flags), @@ -250,7 +250,7 @@ where } } - #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, fh=fh, datasync=datasync))] + #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, fh=fh, datasync=datasync, name=field::Empty))] fn fsync(&self, _req: &Request<'_>, ino: u64, fh: u64, datasync: bool, reply: ReplyEmpty) { match block_on(self.fs.fsync(ino, fh, datasync).in_current_span()) { Ok(()) => reply.ok(), @@ -258,7 +258,7 @@ where } } - #[instrument(level="warn", skip_all, fields(req=req.unique(), ino=ino, fh=fh, pid=req.pid()))] + #[instrument(level="warn", skip_all, fields(req=req.unique(), ino=ino, fh=fh, pid=req.pid(), name=field::Empty))] fn flush(&self, req: &Request<'_>, ino: u64, fh: u64, lock_owner: u64, reply: ReplyEmpty) { match block_on(self.fs.flush(ino, fh, lock_owner, req.pid()).in_current_span()) { Ok(()) => reply.ok(), @@ -266,7 +266,7 @@ where } } - #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, fh=fh))] + #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, fh=fh, name=field::Empty))] fn release( &self, _req: &Request<'_>, @@ -322,7 +322,7 @@ where } } - #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, fh=fh, offset=offset, length=data.len(), pid=_req.pid()))] + #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, fh=fh, offset=offset, length=data.len(), pid=_req.pid(), name=field::Empty))] fn write( &self, _req: &Request<'_>, @@ -365,7 +365,7 @@ where } } - #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino))] + #[instrument(level="warn", skip_all, fields(req=_req.unique(), ino=ino, name=field::Empty))] fn setattr( &self, _req: &Request<'_>, diff --git a/mountpoint-s3/src/inode.rs b/mountpoint-s3/src/inode.rs index 26035e51e..bb761745a 100644 --- a/mountpoint-s3/src/inode.rs +++ b/mountpoint-s3/src/inode.rs @@ -40,6 +40,7 @@ use time::OffsetDateTime; use tracing::{debug, error, trace, warn}; use crate::fs::{CacheConfig, S3Personality}; +use crate::logging; use crate::prefix::Prefix; use crate::sync::atomic::{AtomicU64, Ordering}; use crate::sync::RwLockReadGuard; @@ -139,6 +140,7 @@ impl Superblock { error!("forget called on inode {ino} already removed from the superblock"); } Some(inode) => { + logging::record_name(inode.name()); let new_lookup_count = inode.dec_lookup_count(n); if new_lookup_count == 0 { // Safe to remove, kernel no longer has a reference to it. @@ -209,6 +211,7 @@ impl Superblock { force_revalidate: bool, ) -> Result { let inode = self.inner.get(ino)?; + logging::record_name(inode.name()); if !force_revalidate { let sync = inode.get_inode_state()?; @@ -243,6 +246,7 @@ impl Superblock { mtime: Option, ) -> Result { let inode = self.inner.get(ino)?; + logging::record_name(inode.name()); let mut sync = inode.get_mut_inode_state()?; if sync.write_status == WriteStatus::Remote { @@ -294,6 +298,7 @@ impl Superblock { trace!(dir=?dir_ino, "readdir"); let dir = self.inner.get(dir_ino)?; + logging::record_name(dir.name()); if dir.kind() != InodeKind::Directory { return Err(InodeError::NotADirectory(dir.err())); } @@ -326,7 +331,7 @@ impl Superblock { .await; match existing { Ok(lookup) => return Err(InodeError::FileAlreadyExists(lookup.inode.err())), - Err(InodeError::FileDoesNotExist) => (), + Err(InodeError::FileDoesNotExist(_, _)) => (), Err(e) => return Err(e), } @@ -801,7 +806,7 @@ impl SuperblockInner { InodeKindData::Directory { children, .. } => children.get(name), }; match (remote, inode) { - (None, None) => Err(InodeError::FileDoesNotExist), + (None, None) => Err(InodeError::FileDoesNotExist(name.to_owned(), parent.err())), (Some(remote), Some(existing_inode)) => { let mut existing_state = existing_inode.get_mut_inode_state()?; let existing_is_remote = existing_state.write_status == WriteStatus::Remote; @@ -838,7 +843,7 @@ impl SuperblockInner { InodeKindData::Directory { children, .. } => children.get(name).cloned(), }; match (remote, inode) { - (None, None) => Err(InodeError::FileDoesNotExist), + (None, None) => Err(InodeError::FileDoesNotExist(name.to_owned(), parent.err())), (None, Some(existing_inode)) => { let InodeKindData::Directory { children, @@ -868,7 +873,7 @@ impl SuperblockInner { // being written. It must have previously existed but been removed on the remote // side. children.remove(name); - Err(InodeError::FileDoesNotExist) + Err(InodeError::FileDoesNotExist(name.to_owned(), parent.err())) } } (Some(remote), None) => { @@ -1485,8 +1490,8 @@ impl InodeStat { pub enum InodeError { #[error("error from ObjectClient")] ClientError(#[source] anyhow::Error), - #[error("file does not exist")] - FileDoesNotExist, + #[error("file {0:?} does not exist in parent inode {1}")] + FileDoesNotExist(String, InodeErrorInfo), #[error("inode {0} does not exist")] InodeDoesNotExist(InodeNo), #[error("invalid file name {0:?}")] @@ -2473,7 +2478,7 @@ mod tests { // All nested dirs disappear let dirname = nested_dirs.first().unwrap(); let lookedup = superblock.lookup(&client, FUSE_ROOT_INODE, dirname.as_ref()).await; - assert!(matches!(lookedup, Err(InodeError::FileDoesNotExist))); + assert!(matches!(lookedup, Err(InodeError::FileDoesNotExist(_, _)))); } #[tokio::test] diff --git a/mountpoint-s3/src/logging.rs b/mountpoint-s3/src/logging.rs index 7f117009e..3fe624bb7 100644 --- a/mountpoint-s3/src/logging.rs +++ b/mountpoint-s3/src/logging.rs @@ -12,6 +12,7 @@ use mountpoint_s3_crt::common::rust_log_adapter::RustLogAdapter; use time::format_description::FormatItem; use time::macros; use time::OffsetDateTime; +use tracing::Span; use tracing_subscriber::filter::{EnvFilter, Filtered, LevelFilter}; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::util::SubscriberInitExt; @@ -147,3 +148,7 @@ fn init_tracing_subscriber(config: LoggingConfig) -> anyhow::Result<()> { Ok(()) } + +pub fn record_name(name: &str) -> Span { + Span::current().record("name", name).clone() +} diff --git a/mountpoint-s3/src/prefetch/part_stream.rs b/mountpoint-s3/src/prefetch/part_stream.rs index 96acb535b..5c9f3872e 100644 --- a/mountpoint-s3/src/prefetch/part_stream.rs +++ b/mountpoint-s3/src/prefetch/part_stream.rs @@ -196,7 +196,7 @@ where { Ok(get_object_result) => get_object_result, Err(e) => { - error!(error=?e, "GetObject request failed"); + error!(key, error=?e, "GetObject request failed"); part_queue_producer.push(Err(PrefetchReadError::GetRequestFailed(e))); return; } @@ -227,7 +227,7 @@ where } } Some(Err(e)) => { - error!(error=?e, "GetObject body part failed"); + error!(key, error=?e, "GetObject body part failed"); part_queue_producer.push(Err(PrefetchReadError::GetRequestFailed(e))); break; }