Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add filename at Error and Warn level in logs #665

Merged
merged 5 commits into from
Dec 7, 2023
Merged

Add filename at Error and Warn level in logs #665

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
a5eee1d
Added key in inode.rs
Nov 30, 2023
52e2787
Added filename in warn span
Dec 3, 2023
9ef6b3a
Removed the InodeError distinguishing *deleted marker and other recom…
Dec 6, 2023
0fe4f52
Added parent info in FileDoesNotExist error
Dec 6, 2023
e1cb371
Improved the formatting of FileDoesNotExist error
Dec 6, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 7 additions & 2 deletions mountpoint-s3/src/fs.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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};
Expand Down Expand Up @@ -167,7 +168,7 @@ impl<Client: ObjectClient> UploadState<Client> {
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"),
Expand Down Expand Up @@ -231,7 +232,7 @@ impl<Client: ObjectClient> UploadState<Client> {
};
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
}
Expand Down Expand Up @@ -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")),
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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(()),
Expand Down Expand Up @@ -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,
Expand Down
2 changes: 1 addition & 1 deletion mountpoint-s3/src/fs/error.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
22 changes: 11 additions & 11 deletions mountpoint-s3/src/fuse.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -92,28 +92,28 @@ 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))]
passaro marked this conversation as resolved.
Show resolved Hide resolved
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),
Err(e) => fuse_error!("getattr", reply, e),
}
}

#[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),
Err(e) => fuse_error!("open", reply, e),
}
}

#[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<'_>,
Expand Down Expand Up @@ -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),
Expand Down Expand Up @@ -250,23 +250,23 @@ 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(),
Err(e) => fuse_error!("fsync", reply, e),
}
}

#[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(),
Err(e) => fuse_error!("flush", reply, e),
}
}

#[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<'_>,
Expand Down Expand Up @@ -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<'_>,
Expand Down Expand Up @@ -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<'_>,
Expand Down
19 changes: 12 additions & 7 deletions mountpoint-s3/src/inode.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -209,6 +211,7 @@ impl Superblock {
force_revalidate: bool,
) -> Result<LookedUp, InodeError> {
let inode = self.inner.get(ino)?;
logging::record_name(inode.name());

if !force_revalidate {
let sync = inode.get_inode_state()?;
Expand Down Expand Up @@ -243,6 +246,7 @@ impl Superblock {
mtime: Option<OffsetDateTime>,
) -> Result<LookedUp, InodeError> {
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 {
Expand Down Expand Up @@ -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()));
}
Expand Down Expand Up @@ -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),
}

Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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) => {
Expand Down Expand Up @@ -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:?}")]
Expand Down Expand Up @@ -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]
Expand Down
5 changes: 5 additions & 0 deletions mountpoint-s3/src/logging.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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()
}
4 changes: 2 additions & 2 deletions mountpoint-s3/src/prefetch/part_stream.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down Expand Up @@ -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;
}
Expand Down
Loading