[#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");

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, 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-10T22:53:45.511134Z DEBUG gvfs_fuse::fuse_api_handle: get_modified_file_stat file_id=1 filename="" size=None atime= mtime=
2025-01-10T22:53:45.511157Z DEBUG gvfs_fuse::fuse_api_handle_debug: rmdir started req.unique=2 req=Request { unique: 2, uid: 501, gid: 20, pid: 90853 } parent="" name="test_dir"
2025-01-10T22:53:45.511192Z DEBUG gvfs_fuse::fuse_api_handle_debug: rmdir succeeded req.unique=2
2025-01-10T22:53:45.511297Z DEBUG gvfs_fuse::fuse_api_handle: get_modified_file_stat file_id=1 filename="" size=None atime= mtime=
2025-01-10T22:53:45.511316Z DEBUG gvfs_fuse::fuse_api_handle_debug: lookup started req.unique=7 req=Request { unique: 7, uid: 501, gid: 20, pid: 90853 } parent="" name="._test_dir"
2025-01-10T22:53:45.511337Z ERROR gvfs_fuse::fuse_api_handle_debug: lookup failed req.unique=7 e=Errno(2)
2025-01-10T22:53:45.511433Z DEBUG gvfs_fuse::fuse_api_handle: get_modified_file_stat file_id=1 filename="" size=None atime= mtime=
2025-01-10T22:53:45.511450Z DEBUG gvfs_fuse::fuse_api_handle_debug: lookup started req.unique=6 req=Request { unique: 6, uid: 501, gid: 20, pid: 90853 } parent="" name="test_dir"
2025-01-10T22:53:45.511469Z ERROR gvfs_fuse::fuse_api_handle_debug: lookup failed req.unique=6 e=Errno(2)
2025-01-10T22:53:45.511716Z DEBUG gvfs_fuse::fuse_api_handle_debug: destroy started req.unique=0 req=Request { unique: 0, uid: 0, gid: 0, pid: 0 }

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.

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

clients/filesystem-fuse/src/fuse_api_handle.rs

+            inner: FuseApiHandle::new(fs, context),
+        }
+    }
+


These functions that are not part of the Filesystem trait do not need to add debug logs.

new is needed, we can use it to create a FuseApiHandleDebug, and it will create a FuseApiHandle as inner file system.

e.g.

let fs = DefaultRawFileSystem::new(gvfs); FuseApiHandleDebug::new(fs, fs_context)

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.

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

clients/filesystem-fuse/src/fuse_api_handle.rs

+    async fn init(&self, req: Request) -> fuse3::Result<ReplyInit> {
+        debug!("init: req: {:?}", req);
+        let result = self.inner.init(req).await;
+        debug!("init result: {:?}", result);


This is an asynchronous multithreaded model. Logs from two print statements within a single function may be interleaved with logs from other interfaces. It is necessary to identify them in the logs.

Okay, I use Request.unique as the unique identifier of the request.

2024-12-28T12:23:01.966929Z DEBUG gvfs_fuse::fuse_api_handle: lookup [id=6]: error: Errno(2) 2024-12-28T12:23:01.967037Z DEBUG gvfs_fuse::fuse_api_handle: lookup [id=7]: req: Request { unique: 7, uid: 501, gid: 20, pid: 18890 }, parent: 1, name: "test_create" 2024-12-28T12:23:01.967056Z DEBUG gvfs_fuse::fuse_api_handle: lookup [id=7]: reply: ReplyEntry { ttl: 1s, attr: FileAttr { ino: 10001, size: 0, blocks: 0, atime: Timestamp { sec: 1735388581, nsec: 967051000 }, mtime: Timestamp { sec: 1735388581, nsec: 967051000 }, ctime: Timestamp { sec: 1735388581, nsec: 967051000 }, crtime: Timestamp { sec: 1735388581, nsec: 967051000 }, kind: RegularFile, perm: 420, nlink: 1, uid: 501, gid: 20, rdev: 0, flags: 0, blksize: 4096 }, generation: 0 }

diqiu50 · 2024-12-20T01:58:45Z

clients/filesystem-fuse/src/fuse_api_handle.rs

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


If an error is returned, it should be logged using error!.

diqiu50 · 2024-12-20T02:05:02Z

clients/filesystem-fuse/src/fuse_api_handle.rs

+        atime: Option<Timestamp>,
+        mtime: Option<Timestamp>,
+    ) -> Result<FileStat, Errno> {
+        debug!("get_modified_file_stat: file_id: {}, size: {:?}, atime: {:?}, mtime: {:?}", file_id, size, atime, mtime);


It’s best to convert file_id to a file path to improve readability, for example, "/a/b.txt(2342)". Other variables should follow a similar approach.

implemented at a7073a0.

I use a wrapper struct TimestampDebug which implement custom fmt::Display trait,
now, Timestamp will be displayed like:

mtime: Timestamp { sec: 1735386080, nsec: 26884000 }, ctime: Timestamp { sec: 1735386080, nsec: 26884000 }, crtime: Timestamp { sec: 1735386080, nsec: 26884000 }

I implemented some methods like reply_attr_to_desc_str, reply_entry_to_desc_str to manually control the format.

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.

diqiu50 · 2024-12-30T06:35:58Z

clients/filesystem-fuse/src/fuse_api_handle.rs

+            "readdir [id={}]: req: {:?}, parent: {:?}, fh: {:?}, offset: {:?}",
+            req.unique, req, parent, fh, offset
+        );
+        let result = self.inner.readdir(req, parent, fh, offset).await;


Need to show dir entries

diqiu50 · 2024-12-30T06:37:15Z

clients/filesystem-fuse/src/fuse_api_handle.rs

+impl fmt::Display for TimestampDebug {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        let ts = &self.0; // Access the inner `Timestamp`
+        write!(f, "{}.{:09}", ts.sec, ts.nsec) // Nanoseconds padded to 9 digits


The result of timestamp is not readable.
I think the TimestampDebug is not god for use. You can try to find a better solution.
At least you can use a function to convert it into a readable time format

I implemented some methods like reply_attr_to_desc_str, reply_entry_to_desc_str to manually control the format.

diqiu50 · 2024-12-30T06:55:58Z

clients/filesystem-fuse/src/fuse_api_handle.rs

+
+pub(crate) struct FuseApiHandleDebug<T: RawFileSystem> {
+    inner: FuseApiHandle<T>,
+}


separate this class as a new file

diqiu50 · 2024-12-30T06:57:29Z

clients/filesystem-fuse/src/fuse_api_handle.rs

+            }
+            Err(e) => {
+                debug!("init [id={}]: error: {:?}", req.unique, e);
+                Err(e)


Is using error! better?

Yeah, error! is better, fixed.

diqiu50 · 2024-12-30T07:02:08Z

clients/filesystem-fuse/src/fuse_api_handle.rs

+                    req.unique,
+                    FileAttrDebug {
+                        file_attr: &reply.attr
+                    }


Constructing an object is not as clear as using a function like to_desc_string()

I implemented some methods like reply_attr_to_desc_str, reply_entry_to_desc_str to manually control the format.

diqiu50 · 2024-12-30T07:03:36Z

clients/filesystem-fuse/src/fuse_api_handle.rs

+        let result = self.inner.read(req, inode, fh, offset, size).await;
+        match result {
+            Ok(reply) => {
+                debug!("read [id={}]: reply: {:?}", req.unique, reply);


The result of is not clear enough.

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

diqiu50 · 2024-12-30T07:05:25Z

clients/filesystem-fuse/src/fuse_api_handle.rs

+    ) -> fuse3::Result<ReplyDirectoryPlus<Self::DirEntryPlusStream<'a>>> {
+        debug!(
+            "readdirplus [id={}]: req: {:?}, parent: {:?}, fh: {:?}, offset: {:?}, lock_owner: {:?}",
+            req.unique, req, parent, fh, offset, lock_owner


It would be better to print the filename as well.

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)

…r Result

…o make log more readable

…ied_file_stat

…n get_modified_file_stat

…ring

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.

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

unknowntpo changed the title ~~Feat fuse debug log~~ [#5873] feat(gvfs-fuse): add debug log for FuseApiHandle Dec 20, 2024

unknowntpo force-pushed the feat-fuse-debug-log branch from d1bfdba to 425c490 Compare December 26, 2024 02:47

unknowntpo closed this Dec 29, 2024

unknowntpo reopened this Dec 29, 2024

diqiu50 reviewed Dec 30, 2024

View reviewed changes

unknowntpo force-pushed the feat-fuse-debug-log branch from 1d9ff8a to d619db0 Compare January 3, 2025 02:39

unknowntpo force-pushed the feat-fuse-debug-log branch 2 times, most recently from d4627de to ec48523 Compare January 7, 2025 23:14

unknowntpo changed the base branch from branch-gvfs-fuse-dev to main January 7, 2025 23:17

unknowntpo force-pushed the feat-fuse-debug-log branch from 3defb39 to 136ec63 Compare January 10, 2025 02:19

unknowntpo added 3 commits January 11, 2025 06:56

refactor: fix rebase problem

0c1b750

fix(fuse:filesystem.rs): wip: add Debug trait to FileSystemContext

69d42b3

feat: implement FuseApiHandleDebug

8f72e80

unknowntpo added 23 commits January 11, 2025 06:56

fix rebase error

f590645

revert unnecesary change

9ffd0bf

fix(gvfs/fuse_test.rs): should use tracing_subscriber::fmt::init()

d67ec87

feat(gvfs_fuse::fuse_api_handle): tweak log

23f1fd5

feat(gvfs_fuse::fuse_api_handle): tweak log, add debugging message fo…

d157e0e

…r Result

feat(gvfs_fuse::fuse_api_handle): add TimestampDebug, FileAttrDebug t…

f1913b8

…o make log more readable

feat(gvfs_fuse::fuse_api_handle): improve debug message for get_modif…

efc7e50

…ied_file_stat

feat(gvfs_fuse::fuse_api_handle): log file_stat in getattr

ef4fc64

feat(gvfs_fuse::fuse_api_handle): tweak logging format of Timestamp i…

eeaf785

…n get_modified_file_stat

styles: apply cargo fmt

c6d2c31

minor: apply formatting

77a1edd

refactor: extract FuseApiHandleDebug to new file

aaa1ddc

refactor: tweak gvfs_fuse.rs due to rebase

b0e7259

refactor: implement timestamp_to_readable_time_string

a75ee45

docs(fuse_api_handle_debug): add doc of timestamp_to_readable_time_st…

41a1837

…ring

refactor: use error! to log message if result is Err

e27b8e3

wip: use structure logging with tracing pacakge

91ee971

feat: show file / dir name in log

ae9341b

feat: show file / dir name in log

0256bc9

refactor: rename Timestamp formatting function

2dd85cc

feat: implement reply_attr_to_desc_str

90bb633

refactor: remove FileAttrDebug

d20fef4

feat: implement string format method for ReplyEntry, ReplyCreated

87e01ff

unknowntpo force-pushed the feat-fuse-debug-log branch from 479e7be to 87e01ff Compare January 10, 2025 22:57

unknowntpo added 4 commits January 11, 2025 07:03

style(: format the code

9acdc4c

refactor: remove unused import

ef22880

refactor: skip clippy::needless_lifetimes check

3038447

style(Cargo.toml): sort deps

03a6e3f

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

unknowntpo commented Dec 18, 2024 •

edited

Loading

diqiu50 left a comment

diqiu50 Dec 20, 2024

unknowntpo Dec 29, 2024

diqiu50 Dec 20, 2024

diqiu50 Dec 20, 2024

unknowntpo Dec 29, 2024

diqiu50 Dec 20, 2024

diqiu50 Dec 20, 2024

unknowntpo Dec 29, 2024

unknowntpo Jan 10, 2025 •

edited

Loading

diqiu50 commented Dec 20, 2024

unknowntpo commented Dec 26, 2024 •

edited

Loading

unknowntpo commented Dec 29, 2024

xunliu commented Dec 30, 2024

diqiu50 Dec 30, 2024

unknowntpo Jan 10, 2025

diqiu50 Dec 30, 2024 •

edited

Loading

unknowntpo Jan 10, 2025

diqiu50 Dec 30, 2024

diqiu50 Dec 30, 2024

unknowntpo Jan 10, 2025

diqiu50 Dec 30, 2024

unknowntpo Jan 10, 2025

diqiu50 Dec 30, 2024

unknowntpo Jan 10, 2025

diqiu50 left a comment

diqiu50 Dec 30, 2024

unknowntpo Jan 10, 2025

diqiu50 commented Jan 6, 2025

unknowntpo commented Jan 6, 2025

unknowntpo commented Jan 10, 2025

unknowntpo commented Jan 10, 2025

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

Are you sure you want to change the base?

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

Conversation

unknowntpo commented Dec 18, 2024 • edited Loading

What changes were proposed in this pull request?

Does this PR introduce any user-facing change?

How was this patch tested?

diqiu50 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

unknowntpo Jan 10, 2025 • edited Loading

Choose a reason for hiding this comment

diqiu50 commented Dec 20, 2024

unknowntpo commented Dec 26, 2024 • edited Loading

unknowntpo commented Dec 29, 2024

xunliu commented Dec 30, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

diqiu50 Dec 30, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

diqiu50 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

diqiu50 commented Jan 6, 2025

unknowntpo commented Jan 6, 2025

unknowntpo commented Jan 10, 2025

unknowntpo commented Jan 10, 2025

unknowntpo commented Dec 18, 2024 •

edited

Loading

unknowntpo Jan 10, 2025 •

edited

Loading

unknowntpo commented Dec 26, 2024 •

edited

Loading

diqiu50 Dec 30, 2024 •

edited

Loading