[#5873] feat(gvfs-fuse): add debug log for FuseApiHandle #5905

unknowntpo · 2024-12-18T08:47:14Z

What changes were proposed in this pull request?

Implement FuseApiHandleDebug so we can log all input arguments and return values of FuseApiHandle.
I use tracing::debug, tracing::error with structure logging to format the message in key value pair format, so we don't need to control format manually.

e.g.

        debug!(req.unique, ?req, parent = ?parent_stat.name, ?name, "lookup started");

And user can set fuse_debug = true in [fuse] section at config file like gvfs_fuse_memory.toml to decide whether they need fuse debug logging or not.

Fix: #5873

Does this PR introduce any user-facing change?

No.

How was this patch tested?

tested with fuse_test.rs, along with MemoryFileSystem.

Now, FuseApiHandleDebug will wrap FuseApiHandle and log all input arguments and returned values, if return value is Result, we use match to extract and log the status of result, note that error will be logged if occured.

To test this PR, set fuse_debug = true in gvfs_fuse_memory.toml and run:

cd ./clients/filesystem-fuse
RUST_LOG=gvfs_fuse::fuse_api_handle=debug make test

Here's some example logging generated by test_fuse_system_with_auto in fuse_test.rs:

2025-01-16T02:59:13.860193Z DEBUG gvfs_fuse::fuse_api_handle_debug: lookup started req.unique=4 req=Request { unique: 4, uid: 501, gid: 20, pid: 430 } parent="" name="._."
2025-01-16T02:59:13.860211Z ERROR gvfs_fuse::fuse_api_handle_debug: lookup failed req.unique=4 e=Errno(2)
2025-01-16T02:59:13.860371Z DEBUG gvfs_fuse::fuse_api_handle_debug: statfs started req.unique=5 req=Request { unique: 5, uid: 501, gid: 20, pid: 430 } filename=""
2025-01-16T02:59:13.860382Z DEBUG gvfs_fuse::fuse_api_handle_debug: statfs completed req.unique=5 reply=ReplyStatFs { blocks: 1000000, bfree: 1000000, bavail: 1000000, files: 1000000, ffree: 1000000, bsize: 4096, namelen: 255, frsize: 4096 }

...

2025-01-16T02:59:14.840096Z DEBUG gvfs_fuse::fuse_api_handle_debug: setattr started req.unique=2 req=Request { unique: 2, uid: 501, gid: 20, pid: 22343 } filename="test_create" fh=Some(1) set_attr=SetAttr { mode: None, uid: None, gid: None, size: Some(0), lock_owner: None, atime: None, mtime: None, ctime: None, crtime: None, chgtime: None, bkuptime: None, flags: None }
2025-01-16T02:59:14.840243Z DEBUG gvfs_fuse::fuse_api_handle_debug: setattr completed req.unique=2 reply=ttl: 1s, FileAttr: { ino: 10000, size: 0, blocks: 0, atime: "2025-01-16 02:59:14.840213", mtime: "2025-01-16 02:59:14.840213", ctime: "2025-01-16 02:59:14.840213", crtime: "2025-01-16 02:59:14.840213", kind: RegularFile, perm: 600, nlink: 1, uid: 501, gid: 20, rdev: 0, flags: 0, blksize: 8192 }

...

diqiu50

Finally, we need to verify the log format to see if it meets expectations. This needs to be validated in the #5886, and you can wait for it to be merged.

clients/filesystem-fuse/src/fuse_api_handle.rs

diqiu50 · 2024-12-20T01:55:57Z

clients/filesystem-fuse/src/fuse_api_handle.rs

+}
+
+impl<T: RawFileSystem> Filesystem for FuseApiHandleDebug<T> {
+    async fn init(&self, req: Request) -> fuse3::Result<ReplyInit> {


We need to implement all interfaces of the Filesystem. If they are not implemented yet, an error log should be recorded.

Do you implement all the Filesystem interfaces?

clients/filesystem-fuse/src/fuse_api_handle.rs

diqiu50 · 2024-12-20T02:06:10Z

Please refer to other PRs for the format of PR titles and descriptions.

unknowntpo · 2024-12-26T02:43:48Z

Finally, we need to verify the log format to see if it meets expectations. This needs to be validated in the #5886, and you can wait for it to be merged.

Since #5886 is done, I'll continue on my work.

unknowntpo · 2024-12-29T14:24:59Z

close and reopen to run workflow

xunliu · 2024-12-30T05:14:11Z

@diqiu50 Please help review this PR, Thanks.

clients/filesystem-fuse/src/fuse_api_handle.rs

diqiu50

Overall, there is no issue. The readability of the logs needs to be improved and made more concise. Unimportant information can be ignored.

Implement a few methods for printing commonly used structures, without having to print them in the struct format

clients/filesystem-fuse/src/fuse_api_handle.rs

diqiu50 · 2025-01-06T03:07:53Z

@unknowntpo All the code are merged to the main brach. you need to merge the pr to main

unknowntpo · 2025-01-06T03:10:41Z

@diqiu50 Okay, (I'm still working this PR)

unknowntpo · 2025-01-10T23:25:51Z

Note that I use tracing::debug, tracing::error with structure logging to format the message in key value pair format, so we don't need to control format manually.

e.g.

    debug!(req.unique, ?req, parent = ?parent_stat.name, ?name, "lookup started");

unknowntpo · 2025-01-10T23:28:28Z

@diqiu50 Done, please take a look.

…ault max debug level to be INFO

…og_get_file_path_result

diqiu50 · 2025-03-06T02:46:48Z

clients/filesystem-fuse/src/fuse_api_handle_debug.rs

+            }
+        }
+    }};
+}


What's the difference between the macro of log_readdirplus and log_readdir, I think you can make a macro to instead them.

The format function and return type is different (for readdir, we need ReplyDirectory, for readdirplus, we need ReplyDirectoryPlus`), if I make them use the same macro:

/// Log the result for readdir operations macro_rules! log_readdir { ($method_call:expr, $req:ident, $reply_type:ident) => {{ match $method_call.await { Ok(mut reply_dir) => { let mut entries = Vec::new(); while let Some(entry_result) = reply_dir.entries.next().await { match entry_result { Ok(entry) => { entries.push(entry); } Err(e) => { return Err(e.into()); } } } let format_fn = if stringify!($reply_type) == "ReplyDirectory" { directory_entry_to_desc_str } else { directory_entry_plus_to_desc_str }; let entries_info = format!( "[{}]", entries .iter() .map(|entry| format_fn(entry)) .collect::<Vec<String>>() .join(", ") ); debug!($req.unique, entries = entries_info, "READDIR completed"); if stringify!($reply_type) == "ReplyDirectory" { Ok(ReplyDirectory { entries: stream::iter(entries.into_iter().map(Ok)).boxed(), }) } else { Ok(ReplyDirectoryPlus { entries: stream::iter(entries.into_iter().map(Ok)).boxed(), }) } } Err(e) => { error!($req.unique, ?e, "READDIR failed"); Err(e) } } }}; }

In readdir:

log_readdir!( self.inner.readdir(req, parent, fh, offset), req, ReplyDirectory )

In readdirplus:

log_readdir!( self.inner.readdirplus(req, parent, fh, offset, lock_owner), req, ReplyDirectoryPlus )

I got mismatched type error:

--> src/fuse_api_handle_debug.rs:134:24 | 134 | Ok(ReplyDirectoryPlus { | _____________________--_^ | | | | | arguments to this enum variant are incorrect 135 | | entries: stream::iter(entries.into_iter().map(Ok)).boxed(), 136 | | }) | |_____________________^ expected `ReplyDirectory<Pin<Box<...>>>`, found `ReplyDirectoryPlus<Pin<Box<...>>>` ... 795 | / log_readdir!( 796 | | self.inner.readdir(req, parent, fh, offset), 797 | | req, 798 | | ReplyDirectory 799 | | ) | |_________- in this macro invocation | = note: expected struct `fuse3::raw::reply::ReplyDirectory<Pin<Box<dyn Stream<Item = std::result::Result<fuse3::raw::reply::DirectoryEntry, Errno>> + std::marker::Send>>>` found struct `fuse3::raw::reply::ReplyDirectoryPlus<Pin<Box<dyn Stream<Item = std::result::Result<fuse3::raw::reply::DirectoryEntry, _>> + std::marker::Send>>>` help: the type constructed contains `fuse3::raw::reply::ReplyDirectoryPlus<Pin<Box<dyn Stream<Item = std::result::Result<fuse3::raw::reply::DirectoryEntry, _>> + std::marker::Send>>>` due to the type of the argument passed --> src/fuse_api_handle_debug.rs:134:21 | 134 | Ok(ReplyDirectoryPlus { | _____________________^ - | |________________________| 135 | || entries: stream::iter(entries.into_iter().map(Ok)).boxed(), 136 | || }) | ||_____________________-^ | |______________________| | this argument influences the type of `Ok` ... 795 | / log_readdir!( 796 | | self.inner.readdir(req, parent, fh, offset), 797 | | req, 798 | | ReplyDirectory 799 | | ) | |_________- in this macro invocation note: tuple variant defined here --> /Users/unknowntpo/.rustup/toolchains/1.82.0-aarch64-apple-darwin/lib/rustlib/src/rust/library/core/src/result.rs:531:5 | 531 | Ok(#[stable(feature = "rust1", since = "1.0.0")] T), | ^^ = note: this error originates in the macro `log_readdir` (in Nightly builds, run with -Z macro-backtrace for more info) error[E0308]: `if` and `else` have incompatible types --> src/fuse_api_handle_debug.rs:115:21 | 112 | let format_fn = if stringify!($reply_type) == "ReplyDirectory" { | _________________________________- 113 | | directory_entry_to_desc_str | | --------------------------- expected because of this 114 | | } else { 115 | | directory_entry_plus_to_desc_str | | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ expected `fuse3::raw::reply::DirectoryEntry`, found `DirectoryEntryPlus` 116 | | }; | |_________________- `if` and `else` have incompatible types ... 885 | / log_readdir!( 886 | | self.inner.readdirplus(req, parent, fh, offset, lock_owner), 887 | | req, 888 | | ReplyDirectoryPlus 889 | | ) | |_________- in this macro invocation | = note: expected fn item `for<'a> fn(&'a fuse3::raw::reply::DirectoryEntry) -> std::string::String {directory_entry_to_desc_str}` found fn item `for<'a> fn(&'a fuse3::raw::reply::DirectoryEntryPlus) -> std::string::String {directory_entry_plus_to_desc_str}` = note: this error originates in the macro `log_readdir` (in Nightly builds, run with -Z macro-backtrace for more info) error[E0271]: type mismatch resolving `<Pin<Box<dyn Stream<Item = Result<DirectoryEntryPlus, _>> + Send>> as Stream>::Item == Result<DirectoryEntry, Errno>` --> src/fuse_api_handle_debug.rs:131:34 | 131 | entries: stream::iter(entries.into_iter().map(Ok)).boxed(), | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ expected `Result<DirectoryEntry, Errno>`, found `Result<DirectoryEntryPlus, _>` ... 885 | / log_readdir!( 886 | | self.inner.readdirplus(req, parent, fh, offset, lock_owner), 887 | | req, 888 | | ReplyDirectoryPlus 889 | | ) | |_________- in this macro invocation | = note: expected enum `std::result::Result<fuse3::raw::reply::DirectoryEntry, Errno>` found enum `std::result::Result<fuse3::raw::reply::DirectoryEntryPlus, _>` note: required by a bound in `fuse3::raw::reply::ReplyDirectory` --> /Users/unknowntpo/.cargo/registry/src/index.crates.io-6f17d22bba15001f/fuse3-0.8.1/src/raw/reply.rs:253:37 | 253 | pub struct ReplyDirectory<S: Stream<Item = Result<DirectoryEntry>>> { | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ required by this bound in `ReplyDirectory` = note: this error originates in the macro `log_readdir` (in Nightly builds, run with -Z macro-backtrace for more info) error[E0308]: mismatched types --> src/fuse_api_handle_debug.rs:130:24 | 130 | Ok(ReplyDirectory { | _____________________--_^ | | | | | arguments to this enum variant are incorrect 131 | | entries: stream::iter(entries.into_iter().map(Ok)).boxed(), 132 | | }) | |_____________________^ expected `ReplyDirectoryPlus<Pin<Box<...>>>`, found `ReplyDirectory<Pin<Box<...>>>` ... 885 | / log_readdir!( 886 | | self.inner.readdirplus(req, parent, fh, offset, lock_owner), 887 | | req, 888 | | ReplyDirectoryPlus 889 | | ) | |_________- in this macro invocation | = note: expected struct `fuse3::raw::reply::ReplyDirectoryPlus<Pin<Box<dyn Stream<Item = std::result::Result<fuse3::raw::reply::DirectoryEntryPlus, Errno>> + std::marker::Send>>>` found struct `fuse3::raw::reply::ReplyDirectory<Pin<Box<dyn Stream<Item = std::result::Result<fuse3::raw::reply::DirectoryEntryPlus, _>> + std::marker::Send>>>` help: the type constructed contains `fuse3::raw::reply::ReplyDirectory<Pin<Box<dyn Stream<Item = std::result::Result<fuse3::raw::reply::DirectoryEntryPlus, _>> + std::marker::Send>>>` due to the type of the argument passed --> src/fuse_api_handle_debug.rs:130:21 | 130 | Ok(ReplyDirectory { | _____________________^ - | |________________________| 131 | || entries: stream::iter(entries.into_iter().map(Ok)).boxed(), 132 | || }) | ||_____________________-^ | |______________________| | this argument influences the type of `Ok` ... 885 | / log_readdir!( 886 | | self.inner.readdirplus(req, parent, fh, offset, lock_owner), 887 | | req, 888 | | ReplyDirectoryPlus 889 | | ) | |_________- in this macro invocation note: tuple variant defined here --> /Users/unknowntpo/.rustup/toolchains/1.82.0-aarch64-apple-darwin/lib/rustlib/src/rust/library/core/src/result.rs:531:5 | 531 | Ok(#[stable(feature = "rust1", since = "1.0.0")] T), | ^^ = note: this error originates in the macro `log_readdir` (in Nightly

I try using this macro, it's ok:

/// Log the result for readdir operations macro_rules! log_readdir { ($method_call:expr, $req:ident, $entry_to_desc_str:expr, $reply_type:ident) => {{ match $method_call.await { Ok(mut reply_dir) => { let mut entries = Vec::new(); while let Some(entry_result) = reply_dir.entries.next().await { match entry_result { Ok(entry) => { entries.push(entry); } Err(e) => { return Err(e.into()); } } } let entries_info = format!( "[{}]", entries .iter() .map($entry_to_desc_str) .collect::<Vec<String>>() .join(", ") ); debug!($req.unique, entries = entries_info, "READDIR operation completed"); Ok($reply_type { entries: stream::iter(entries.into_iter().map(Ok)).boxed(), }) } Err(e) => { error!($req.unique, ?e, "READDIR operation failed"); Err(e) } } }}; }

diqiu50 · 2025-03-06T02:48:46Z

clients/filesystem-fuse/src/fuse_api_handle_debug.rs

+fn directory_entry_plus_to_desc_str(entry: &DirectoryEntryPlus) -> String {
+    let mut output = String::new();
+    write!(output, "{{ inode: {}, generation: {}, kind: {:?}, name: {}, offset: {}, attr: {}, entry_ttl: {:?}, attr_ttl: {:?} }}", entry.inode, entry.generation, entry.kind, entry.name.to_string_lossy(), entry.offset, file_attr_to_desc_str(&entry.attr), entry.entry_ttl, entry.attr_ttl).unwrap();
+


This line is too long

ok, I've split the code to multi lines.

diqiu50 · 2025-03-06T02:54:31Z

clients/filesystem-fuse/src/fuse_api_handle_debug.rs

+    }
+
+    async fn lookup(&self, req: Request, parent: Inode, name: &OsStr) -> fuse3::Result<ReplyEntry> {
+        let parent_path_name = self.inner.get_file_path(parent).await?;


The get file path logic should not return an error. You need to wrap a function in this class so that if self.inner.get_file_path returns an error, this function returns an empty string ("").

Has this issue been changed?

diqiu50 · 2025-03-10T03:18:36Z

clients/filesystem-fuse/src/main.rs

@@ -193,6 +213,33 @@ fn main() -> Result<(), i32> {
                path.to_string_lossy().to_string()
            };

+            if env::var("RUST_LOG").is_ok() {
+                init_tracing_subscriber(LevelFilter::INFO, "");


We should not override the logging behavior controlled by RUST_LOG.

diqiu50 · 2025-03-10T03:19:44Z

clients/filesystem-fuse/src/main.rs

+                app_config.fuse.fuse_debug = debug > 0 || app_config.fuse.fuse_debug;
+                match debug {
+                    0 => {
+                        init_tracing_subscriber(LevelFilter::INFO, "");


The level 0 is default. same as using RUST_LOG

What needs to be done here:
1. RUST_LOG should control the global logging behavior. We should not override RUST_LOG.
2. When the parameter debug != 0:
• If RUST_LOG is set, use its value and append gvfs_fuse::fuse_api_handle_debug=debug without overriding RUST_LOG.
• Example: If RUST_LOG=trace, keep the trace level and just enable FuseApiHandleDebug. If RUST_LOG=info, set gvfs_fuse::fuse_api_handle_debug=debug along with the original RUST_LOG setting, ensuring that FuseApiHandleDebug is enabled.

This ensures that RUST_LOG’s original behavior is preserved while dynamically enabling FuseApiHandleDebug.

@diqiu50

I have a question:

Does your statements implies that:

if debug == 0:

use RUST_LOG's value as directives.

if debug != 0:

if RUST_LOG has value, then the directive becomes: <RUST_LOG_value>,gvfs_fuse::fuse_api_handle_debug=debug ?

if RUST_LOG is not set, we simply set directives as gvfs_fuse::fuse_api_handle_debug=debug ?

What I not quite sure is:

When the parameter debug != 0:
• If RUST_LOG is set, use its value and append gvfs_fuse::fuse_api_handle_debug=debug without overriding RUST_LOG.

Does this means that if debug != 0, whatever RUST_LOG value is, we just set gvfs_fuse::fuse_api_handle_debug as debug level ?

My point is that if the user sets RUST_LOG='info' and debug=1, the log level is equivalent to RUST_LOG="info, gvfs_fuse=debug".

If RUST_LOG="info, open_dal=debug, s3=debug" and debug=1, the actual effect should be RUST_LOG="info, open_dal=debug, s3=debug, gvfs_fuse=debug".

If RUST_LOG="gvfs_fuse=debug" and debug=1, the actual effect should be RUST_LOG="gvfs_fuse=debug".

If RUST_LOG="gvfs_fuse=trace" and debug=1, the actual effect should be RUST_LOG="gvfs_fuse=trace".

Of course, debug=1 requires enabling FuseApiHandleDebug.

That is to say, the default behavior of the Log module remains unchanged. When debug=1, if the log level of gvfs_fuse is higher than debug, gvfs_fuse=debug is appended, and FuseApiHandleDebug is enabled.

So the purpose of debug flag is for controlling the debug level of the whole gvfs_fuse package, right ? And for debug=1, we now enable gvfs_fuse::fuse_api_handle_debug=debug.

I want to list some examples to make sure my understanding is correct:

When debug == 0 t, we use value of RUST_LOG as directives, the actual effect should be RUST_LOG="<original_rust_log_value>".

when debug != 0, we particularly we need to append gvfs_fuse::fuse_api_handle_debug=debug to the value of RUST_LOG, the actual effect should be RUST_LOG="<original_rust_log_value>,gvfs_fuse::fuse_api_handle_debug=debug". This make sure that no matter which level is set by RUST_LOG for gvfs_fuse, gvfs_fuse::fuse_api_handle_debug still has debug level.

I ask this because at here,

When the parameter debug != 0:
• If RUST_LOG is set, use its value and append gvfs_fuse::fuse_api_handle_debug=debug without overriding RUST_LOG.

you use the words gvfs_fuse::fuse_api_handle_debug=debug.

but at here,

My point is that if the user sets RUST_LOG='info' and debug=1, the log level is equivalent to RUST_LOG="info, gvfs_fuse=debug".

you use the word gvfs_fuse=debug

you say gvfs_fuse=debug, does it mean the whole gvfs_fuse or just an abbreviation of gvfs_fuse::fuse_api_handle_debug ?

I mean the whole gvfs-fuse

diqiu50 · 2025-03-10T03:34:27Z

@unknowntpo Thank you ,this PR is almost ready, just a few minor issues left.
I'm sorry, I have been working on a project with a tight schedule. If the review is not timely, you can @ me on Slack.

…for readablility

unknowntpo · 2025-03-12T01:46:39Z

@unknowntpo Thank you ,this PR is almost ready, just a few minor issues left. I'm sorry, I have been working on a project with a tight schedule. If the review is not timely, you can @ me on Slack.

Really appreciate that you spent time to review my code!
Ok~ I'll mention you in slack.

unknowntpo force-pushed the feat-fuse-debug-log branch 2 times, most recently from 9ae9ea0 to 3574bce Compare December 19, 2024 22:48

unknowntpo marked this pull request as ready for review December 19, 2024 22:52

diqiu50 reviewed Dec 20, 2024

View reviewed changes