This is an automated email from the ASF dual-hosted git repository. diqiu50 pushed a commit to branch main in repository https://gitbox.apache.org/repos/asf/gravitino.git
The following commit(s) were added to refs/heads/main by this push: new f5d44f94f7 [#5873] feat(gvfs-fuse): add debug log for FuseApiHandle (#5905) f5d44f94f7 is described below commit f5d44f94f74d4400de7e6a2d1a1f7937956b4d6e Author: Eric Chang <e850...@gmail.com> AuthorDate: Thu Mar 20 20:41:33 2025 +0800 [#5873] feat(gvfs-fuse): add debug log for FuseApiHandle (#5905) <!-- 1. Title: [#<issue>] <type>(<scope>): <subject> Examples: - "[#123] feat(operator): support xxx" - "[#233] fix: check null before access result in xxx" - "[MINOR] refactor: fix typo in variable name" - "[MINOR] docs: fix typo in README" - "[#255] test: fix flaky test NameOfTheTest" Reference: https://www.conventionalcommits.org/en/v1.0.0/ 2. If the PR is unfinished, please mark this PR as draft. --> ### What changes were proposed in this pull request? Implement `FuseApiHandleDebug` so we can log all input arguments and the results of `FuseApiHandle`. And user can use following methods to enable this feature: - Set `fuse_debug = true` in `[fuse] section` at fuse config file - Run fuse program with `-d 1` flag. eg. ` ./target/debug/gvfs-fuse mount target/gvfs gvfs://fileset/test/c1/s1/fileset1 -c conf/gvfs_fuse.toml -f -d 1` - pass `RUST_LOG=gvfs_fuse=debug` to show debug message` of `gvfs_fuse`. Fix: #5873 ### Does this PR introduce _any_ user-facing change? Yes. ### How was this patch tested? tested with `fuse_test.rs`, along with `MemoryFileSystem`. To test this PR, run the following commands: ``` cd ./clients/filesystem-fuse make build ``` To show regular `INFO` level logging: ``` ./target/debug/gvfs-fuse mount target/gvfs gvfs://fileset/test/c1/s1/fileset1 -c conf/gvfs_fuse.toml -f ``` Example output: ``` 2025-03-18T01:59:08.331232Z INFO gvfs_fuse::config: Use configuration file: conf/gvfs_fuse.toml 2025-03-18T01:59:08.332809Z INFO gvfs_fuse::gvfs_fuse: Starting gvfs-fuse server... 2025-03-18T01:59:08.333145Z INFO gvfs_fuse::fuse_server: Starting FUSE filesystem and mounting at /Users/unknowntpo/repo/unknowntpo/gravitino/feat-fuse-debug-log/clients/filesystem-fuse/target/gvfs 2025-03-18T01:59:09.348236Z ERROR gvfs_fuse::fuse_api_handle_debug: LOOKUP failed req.unique=6 e=Errno(2) 2025-03-18T01:59:09.348578Z ERROR gvfs_fuse::fuse_api_handle_debug: LOOKUP failed req.unique=7 e=Errno(2) 2025-03-18T01:59:09.350890Z ERROR gvfs_fuse::fuse_api_handle_debug: LOOKUP failed req.unique=6 e=Errno(2) 2025-03-18T01:59:09.351380Z ERROR gvfs_fuse::fuse_api_handle_debug: LOOKUP failed req.unique=8 e=Errno(2) ... ^C2025-03-18T02:11:41.583750Z INFO gvfs_fuse: Received Ctrl+C, unmounting gvfs... 2025-03-18T02:11:41.583771Z INFO gvfs_fuse::gvfs_fuse: Stopping gvfs-fuse server... 2025-03-18T02:11:41.583786Z INFO gvfs_fuse::fuse_server: Stopping FUSE filesystem... 2025-03-18T02:11:41.592272Z INFO gvfs_fuse::fuse_server: FUSE filesystem unmounted successfully. ``` To show debug output of file operations: ``` ./target/debug/gvfs-fuse mount target/gvfs gvfs://fileset/test/c1/s1/fileset1 -c conf/gvfs_fuse.toml -f -d 1 ``` Example output: ``` 2025-03-18T02:10:35.328834Z INFO gvfs_fuse::config: Use configuration file: conf/gvfs_fuse.toml 2025-03-18T01:54:11.150981Z INFO gvfs_fuse::gvfs_fuse: Starting gvfs-fuse server... 2025-03-18T01:54:11.151271Z INFO gvfs_fuse::fuse_server: Starting FUSE filesystem and mounting at /Users/unknowntpo/repo/unknowntpo/gravitino/feat-fuse-debug-log/clients/filesystem-fuse/target/gvfs 2025-03-18T01:54:12.158827Z DEBUG gvfs_fuse::fuse_api_handle_debug: INIT started req.unique=2 uid=501 gid=20 pid=84096 2025-03-18T01:54:12.159179Z DEBUG gvfs_fuse::fuse_api_handle_debug: INIT completed req.unique=2 reply=ReplyInit { max_write: 16384 } 2025-03-18T01:54:12.159874Z DEBUG gvfs_fuse::fuse_api_handle_debug: STATFS started req.unique=2 uid=501 gid=20 pid=84096 filename="/" file_id=1 2025-03-18T01:54:12.159984Z DEBUG gvfs_fuse::fuse_api_handle_debug: STATFS completed req.unique=2 reply=ReplyStatFs { blocks: 1000000, bfree: 1000000, bavail: 1000000, files: 1000000, ffree: 1000000, bsize: 4096, namelen: 255, frsize: 4096 } ... 2025-03-18T01:54:52.300762Z DEBUG gvfs_fuse::fuse_api_handle_debug: MKDIR started req.unique=4 uid=501 gid=20 pid=84222 parent="/" parent_id=1 name="hello" mode=16877 umask=0 2025-03-18T01:54:52.301063Z DEBUG gvfs_fuse::fuse_api_handle_debug: MKDIR completed req.unique=4 reply="ttl: 1s, FileAttr: { ino: 10000, size: 0, blocks: 1, atime: 2025-03-18 01:54:52.300964, mtime: 2025-03-18 01:54:52.300964, ctime: 2025-03-18 01:54:52.300964, crtime: 2025-03-18 01:54:52.300964, kind: Directory, perm: 700, nlink: 0, uid: 501, gid: 20, rdev: 0, flags: 0, blksize: 8192 }, generation: 0" ... 2025-03-18T01:55:42.998001Z DEBUG gvfs_fuse::fuse_api_handle_debug: READDIR started req.unique=17 uid=501 gid=20 pid=84391 parent="/hello" fh=87 offset=0 2025-03-18T01:55:42.998092Z DEBUG gvfs_fuse::fuse_api_handle_debug: READDIR completed req.unique=17 entries="[{ inode: 10000, kind: Directory, name: ., offset: 1 }, { inode: 1, kind: Directory, name: .., offset: 2 }, { inode: 10003, kind: RegularFile, name: ._world.txt, offset: 3 }, { inode: 10002, kind: RegularFile, name: world.txt, offset: 4 }]" ``` You can also control global log level by `RUST_LOG` environment variable, and if `-d 1` is passed, the log level of `gvfs_fuse` will always be `debug`. i.e. If you set `RUST_LOG` to: ``` RUST_LOG="info,module1=debug,module2=trace" ./target/debug/gvfs-fuse mount target/gvfs gvfs://fileset/test/c1/s1/fileset1 -c conf/gvfs_fuse.toml -f -d 1 ``` `RUST_LOG` is equaivelant to: ``` info,module1=debug,module2=trace,gvfs_fuse=debug ``` Note that if you encountered errors like: ``` 2025-03-18T02:15:23.075659Z ERROR gvfs_fuse: Failed to mount gvfs: IOError(Os { code: 6, kind: Uncategorized, message: "Device not configured" }) ``` This might because the device is not unmounted successfully, just use `mount` to find the device, and `umount` the filesystem and try again: ``` mount | grep gvfs-fuse gvfs-fuse@macfuse1 on /Users/unknowntpo/repo/unknowntpo/gravitino/feat-fuse-debug-log/clients/filesystem-fuse/target/gvfs (macfuse, nodev, nosuid, synchronous, mounted by unknowntpo) umount -f /Users/unknowntpo/repo/unknowntpo/gravitino/feat-fuse-debug-log/clients/filesystem-fuse/target/gvfs ``` --- clients/filesystem-fuse/Cargo.toml | 5 +- clients/filesystem-fuse/README.md | 8 + clients/filesystem-fuse/conf/gvfs_fuse.toml | 1 + clients/filesystem-fuse/src/config.rs | 8 +- clients/filesystem-fuse/src/fuse_api_handle.rs | 5 + .../filesystem-fuse/src/fuse_api_handle_debug.rs | 819 +++++++++++++++++++++ clients/filesystem-fuse/src/fuse_server.rs | 2 +- clients/filesystem-fuse/src/gravitino_client.rs | 6 +- clients/filesystem-fuse/src/gvfs_fuse.rs | 23 +- clients/filesystem-fuse/src/lib.rs | 1 + clients/filesystem-fuse/src/main.rs | 56 +- clients/filesystem-fuse/src/open_dal_filesystem.rs | 2 +- clients/filesystem-fuse/src/s3_filesystem.rs | 2 +- .../tests/conf/gvfs_fuse_memory.toml | 1 + clients/filesystem-fuse/tests/fuse_test.rs | 11 +- 15 files changed, 935 insertions(+), 15 deletions(-) diff --git a/clients/filesystem-fuse/Cargo.toml b/clients/filesystem-fuse/Cargo.toml index e600683689..29b9950242 100644 --- a/clients/filesystem-fuse/Cargo.toml +++ b/clients/filesystem-fuse/Cargo.toml @@ -35,6 +35,7 @@ name = "gvfs_fuse" [dependencies] async-trait = "0.1" bytes = "1.6.0" +chrono = "0.4.39" clap = { version = "4.5.24", features = ["derive"] } config = "0.13" daemonize = "0.5.0" @@ -42,13 +43,13 @@ dashmap = "6.1.0" fuse3 = { version = "0.8.1", "features" = ["tokio-runtime", "unprivileged"] } futures-util = "0.3.30" libc = "0.2.168" -log = "0.4.22" once_cell = "1.20.2" opendal = { version = "0.46.0", features = ["services-s3"] } reqwest = { version = "0.12.9", features = ["json"] } serde = { version = "1.0.216", features = ["derive"] } tokio = { version = "1.38.0", features = ["full"] } -tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } +tracing = "0.1.41" +tracing-subscriber = { version = "0.3.18", features = ["env-filter", "registry"] } urlencoding = "2.1.3" [dev-dependencies] diff --git a/clients/filesystem-fuse/README.md b/clients/filesystem-fuse/README.md index 0cab9ce44e..c95e6b78c3 100644 --- a/clients/filesystem-fuse/README.md +++ b/clients/filesystem-fuse/README.md @@ -97,6 +97,14 @@ target/debug/gvfs-fuse mount target/gvfs gvfs://fileset/test/c1/s1/fileset1 -c c # mount the fileset uri to the local directory target/gvfs target/debug/gvfs-fuse mount target/gvfs gvfs://fileset/test/c1/s1/fileset1 -c conf/gvfs_fuse.toml +# Execute the mount command in the background with debug logging of gvfs_fuse package (this is equivalent to setting environment variable: `RUST_LOG=gvfs_fuse=debug`) +target/debug/gvfs-fuse mount target/gvfs gvfs://fileset/test/c1/s1/fileset1 -c conf/gvfs_fuse.toml -d 1 + +# You can also specify custom log filter by providing `RUST_LOG` environment variable, +# Note that no matter which `RUST_LOG` is provided, if `-d` is `1`, logging of `gvfs_fuse` will always be `DEBUG` level. +# See [tracing-subscriber](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html#directives) documentation for more details +RUST_LOG=info,gvfs_fuse::memory_filesystem=trace target/debug/gvfs-fuse mount target/gvfs gvfs://fileset/test/c1/s1/fileset1 -c conf/gvfs_fuse.toml -d 1 + # Execute the umount command # unmount the fileset from the local directory target/gvfs target/debug/gvfs-fuse umount target/gvfs diff --git a/clients/filesystem-fuse/conf/gvfs_fuse.toml b/clients/filesystem-fuse/conf/gvfs_fuse.toml index 455222ce33..f1d8b46a2f 100644 --- a/clients/filesystem-fuse/conf/gvfs_fuse.toml +++ b/clients/filesystem-fuse/conf/gvfs_fuse.toml @@ -20,6 +20,7 @@ file_mask = 0o600 dir_mask = 0o700 fs_type = "memory" +fuse_debug = true data_dir = "target/gvfs-fuse" [fuse.properties] diff --git a/clients/filesystem-fuse/src/config.rs b/clients/filesystem-fuse/src/config.rs index 890cb7d31d..0b5943fcbe 100644 --- a/clients/filesystem-fuse/src/config.rs +++ b/clients/filesystem-fuse/src/config.rs @@ -19,10 +19,10 @@ use crate::error::ErrorCode::{ConfigNotFound, InvalidConfig}; use crate::utils::GvfsResult; use config::{builder, Config}; -use log::{error, info, warn}; use serde::Deserialize; use std::collections::HashMap; use std::fs; +use tracing::{error, info, warn}; // FuseConfig pub(crate) const CONF_FUSE_FILE_MASK: ConfigEntity<u32> = ConfigEntity::new( @@ -292,6 +292,8 @@ pub struct FuseConfig { pub dir_mask: u32, #[serde(default)] pub fs_type: String, + #[serde(default = "default_fuse_debug")] + pub fuse_debug: bool, #[serde(default)] pub config_file_path: String, #[serde(default)] @@ -302,6 +304,10 @@ pub struct FuseConfig { pub properties: HashMap<String, String>, } +fn default_fuse_debug() -> bool { + true +} + impl FuseConfig { const MODULE_NAME: &'static str = "fuse"; } diff --git a/clients/filesystem-fuse/src/fuse_api_handle.rs b/clients/filesystem-fuse/src/fuse_api_handle.rs index 15679a222b..d89202bf5c 100644 --- a/clients/filesystem-fuse/src/fuse_api_handle.rs +++ b/clients/filesystem-fuse/src/fuse_api_handle.rs @@ -18,6 +18,7 @@ */ use crate::config::AppConfig; +use crate::filesystem; use crate::filesystem::{FileStat, FileSystemContext, RawFileSystem}; use fuse3::path::prelude::{ReplyData, ReplyOpen, ReplyStatFs, ReplyWrite}; use fuse3::path::Request; @@ -76,6 +77,10 @@ impl<T: RawFileSystem> FuseApiHandle<T> { Ok(file_stat) } + + pub async fn get_file_path(&self, file_id: u64) -> filesystem::Result<String> { + self.fs.get_file_path(file_id).await + } } impl<T: RawFileSystem> Filesystem for FuseApiHandle<T> { diff --git a/clients/filesystem-fuse/src/fuse_api_handle_debug.rs b/clients/filesystem-fuse/src/fuse_api_handle_debug.rs new file mode 100644 index 0000000000..56cef39b05 --- /dev/null +++ b/clients/filesystem-fuse/src/fuse_api_handle_debug.rs @@ -0,0 +1,819 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +use crate::config::AppConfig; +use crate::filesystem::{FileSystemContext, RawFileSystem}; +use crate::fuse_api_handle::FuseApiHandle; +use chrono::DateTime; +use fuse3::path::prelude::{ReplyData, ReplyOpen, ReplyStatFs, ReplyWrite}; +use fuse3::path::Request; +use fuse3::raw::prelude::{ + FileAttr, ReplyAttr, ReplyCreated, ReplyDirectory, ReplyDirectoryPlus, ReplyEntry, ReplyInit, +}; +use fuse3::raw::reply::{DirectoryEntry, DirectoryEntryPlus}; +use fuse3::raw::Filesystem; +use fuse3::{Inode, SetAttr, Timestamp}; +use futures_util::stream::{self, BoxStream}; +use futures_util::StreamExt; +use std::ffi::OsStr; +use std::fmt::Write; +use tracing::{debug, error}; + +/// Log the result without printing the reply +macro_rules! log_status { + ($method_call:expr, $method_name:expr, $req:ident) => { + match $method_call.await { + Ok(reply) => { + debug!($req.unique, "{} completed", $method_name.to_uppercase()); + Ok(reply) + } + Err(e) => { + error!($req.unique, ?e, "{} failed", $method_name.to_uppercase()); + Err(e) + } + } + }; +} + +/// Log the result with default Debug formatting +macro_rules! log_value { + ($method_call:expr, $method_name:expr, $req:ident) => { + match $method_call.await { + Ok(reply) => { + debug!( + $req.unique, + ?reply, + "{} completed", + $method_name.to_uppercase() + ); + Ok(reply) + } + Err(e) => { + error!($req.unique, ?e, "{} failed", $method_name.to_uppercase()); + Err(e) + } + } + }; +} +/// Log the result with custom formatting +macro_rules! log_value_custom { + ($method_call:expr, $method_name:expr, $req:ident, $format_reply_fn:ident) => { + match $method_call.await { + Ok(reply) => { + debug!( + $req.unique, + reply = $format_reply_fn(&reply), + "{} completed", + $method_name.to_uppercase() + ); + Ok(reply) + } + Err(e) => { + error!($req.unique, ?e, "{} failed", $method_name.to_uppercase()); + Err(e) + } + } + }; +} + +/// Log the result for readdir operations +macro_rules! log_readdir { + ($method_call:expr, $method_name: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| $entry_to_desc_str(entry)) + .collect::<Vec<String>>() + .join(", ") + ); + + debug!( + $req.unique, + entries = entries_info, + "{} completed", + $method_name.to_uppercase() + ); + + Ok($reply_type { + entries: stream::iter(entries.into_iter().map(Ok)).boxed(), + }) + } + Err(e) => { + error!($req.unique, ?e, "READDIR failed"); + Err(e) + } + } + }}; +} + +/// Convert `ReplyAttr` to descriptive string. +/// +/// Example (pretty-printed for readability): +/// ```text +/// ttl: 1s, +/// FileAttr: { +/// ino: 10000, +/// size: 0, +/// blocks: 0, +/// atime: 2025-01-16 02:42:52.600436, +/// mtime: 2025-01-16 02:42:52.600436, +/// ctime: 2025-01-16 02:42:52.600436, +/// crtime: 2025-01-16 02:42:52.600436, +/// kind: RegularFile, +/// perm: 600, +/// nlink: 1, +/// uid: 501, +/// gid: 20, +/// rdev: 0, +/// flags: 0, +/// blksize: 8192 +/// } +/// ``` +fn reply_attr_to_desc_str(reply_attr: &ReplyAttr) -> String { + let mut output = String::new(); + + write!( + output, + "ttl: {:?}, FileAttr: {}", + reply_attr.ttl, + file_attr_to_desc_str(&reply_attr.attr) + ) + .unwrap(); + + output +} + +/// Convert `ReplyEntry` to descriptive string. +/// +/// Example (pretty-printed for readability): +/// ```text +/// ttl: 1s, +/// FileAttr: { +/// ino: 10001, +/// size: 0, +/// blocks: 1, +/// atime: 2025-01-16 02:42:52.606512, +/// mtime: 2025-01-16 02:42:52.606512, +/// ctime: 2025-01-16 02:42:52.606512, +/// crtime: 2025-01-16 02:42:52.606512, +/// kind: Directory, +/// perm: 700, +/// nlink: 0, +/// uid: 501, +/// gid: 20, +/// rdev: 0, +/// flags: 0, +/// blksize: 8192 +/// }, +/// generation: 0 +/// ``` +fn reply_entry_to_desc_str(reply_entry: &ReplyEntry) -> String { + let mut output = String::new(); + + write!( + output, + "ttl: {:?}, FileAttr: {}, generation: {}", + reply_entry.ttl, + file_attr_to_desc_str(&reply_entry.attr), + reply_entry.generation + ) + .unwrap(); + + output +} + +/// Convert `ReplyCreated` to descriptive string. +/// +/// Example (pretty-printed for readability): +/// ```text +/// ttl: 1s, +/// FileAttr: { +/// ino: 10000, +/// size: 0, +/// blocks: 1, +/// atime: 2025-01-16 02:47:32.126592, +/// mtime: 2025-01-16 02:47:32.126592, +/// ctime: 2025-01-16 02:47:32.126592, +/// crtime: 2025-01-16 02:47:32.126592, +/// kind: RegularFile, +/// perm: 600, +/// nlink: 0, +/// uid: 501, +/// gid: 20, +/// rdev: 0, +/// flags: 0, +/// blksize: 8192 +/// }, +/// generation: 0, +/// fh: 1 +/// ``` +fn reply_created_to_desc_str(reply_created: &ReplyCreated) -> String { + let mut output = String::new(); + + write!( + output, + "ttl: {:?}, FileAttr: {}, generation: {}, fh: {}", + reply_created.ttl, + file_attr_to_desc_str(&reply_created.attr), + reply_created.generation, + reply_created.fh + ) + .unwrap(); + + output +} + +/// Convert `FileAttr` to descriptive string. +/// +/// Example (pretty-printed for readability): +/// ```text +/// { +/// ino: 10000, +/// size: 0, +/// blocks: 1, +/// atime: 2025-01-10 22:53:45.491337, +/// mtime: 2025-01-10 22:53:45.491337, +/// ctime: 2025-01-10 22:53:45.491337, +/// crtime: 2025-01-10 22:53:45.491337, +/// kind: RegularFile, +/// perm: 384, +/// nlink: 0, +/// uid: 501, +/// gid: 20, +/// rdev: 0, +/// flags: 0, +/// blksize: 8192 +/// } +/// ``` +fn file_attr_to_desc_str(attr: &FileAttr) -> String { + let mut output = String::new(); + + write!( + output, + "{{ ino: {}, size: {}, blocks: {}, atime: {}, mtime: {}, ctime: {}, ", + attr.ino, + attr.size, + attr.blocks, + timestamp_to_desc_string(attr.atime), + timestamp_to_desc_string(attr.mtime), + timestamp_to_desc_string(attr.ctime) + ) + .unwrap(); + #[cfg(target_os = "macos")] + { + write!( + output, + "crtime: {}, ", + timestamp_to_desc_string(attr.crtime) + ) + .unwrap(); + } + write!( + output, + "kind: {:?}, perm: {:o}, nlink: {}, uid: {}, gid: {}, rdev: {}, ", + attr.kind, attr.perm, attr.nlink, attr.uid, attr.gid, attr.rdev + ) + .unwrap(); + #[cfg(target_os = "macos")] + { + write!(output, "flags: {}, ", attr.flags).unwrap(); + } + write!(output, "blksize: {} }}", attr.blksize).unwrap(); + + output +} + +/// Convert `Timestamp` to descriptive string. +/// +/// Example output: "2025-01-07 23:01:30.531699" +fn timestamp_to_desc_string(tstmp: Timestamp) -> String { + DateTime::from_timestamp(tstmp.sec, tstmp.nsec) + .unwrap() + .naive_utc() + .to_string() +} + +/// Convert `DirectoryEntry` to descriptive string. +/// +/// Example: `{ inode: 1234, kind: RegularFile, name: "file.txt", offset: 1 }` +fn directory_entry_to_desc_str(entry: &DirectoryEntry) -> String { + let mut output = String::new(); + write!( + output, + "{{ inode: {}, kind: {:?}, name: {}, offset: {} }}", + entry.inode, + entry.kind, + entry.name.to_string_lossy(), + entry.offset + ) + .unwrap(); + output +} + +/// Convert `DirectoryEntryPlus` to descriptive string. +/// +/// Example (pretty-printed for readability): +/// ```text +/// { +/// inode: 1234, +/// generation: 0, +/// kind: RegularFile, +/// name: "file.txt", +/// offset: 1, +/// attr: {...}, +/// entry_ttl: 1s, +/// attr_ttl: 1s +/// } +/// ``` +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(); + + output +} + +pub(crate) struct FuseApiHandleDebug<T: RawFileSystem> { + inner: FuseApiHandle<T>, +} + +impl<T: RawFileSystem> FuseApiHandleDebug<T> { + pub fn new(fs: T, _config: &AppConfig, context: FileSystemContext) -> Self { + Self { + inner: FuseApiHandle::new(fs, _config, context), + } + } + + /// Wrapper for get_file_path that returns an empty string on error + /// instead of propagating the error + async fn get_file_path_or_empty(&self, inode: Inode) -> String { + self.inner + .get_file_path(inode) + .await + .unwrap_or_else(|_| "".to_string()) + } +} + +impl<T: RawFileSystem> Filesystem for FuseApiHandleDebug<T> { + async fn init(&self, req: Request) -> fuse3::Result<ReplyInit> { + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "INIT started" + ); + + log_value!(self.inner.init(req), "init", req) + } + + async fn destroy(&self, req: Request) { + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "DESTROY started" + ); + self.inner.destroy(req).await; + debug!(req.unique, "DESTROY completed"); + } + + async fn lookup(&self, req: Request, parent: Inode, name: &OsStr) -> fuse3::Result<ReplyEntry> { + let parent_path_name = self.get_file_path_or_empty(parent).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "parent" = ?parent_path_name, + "parent_id" = parent, + ?name, + "LOOKUP started" + ); + + log_value_custom!( + self.inner.lookup(req, parent, name), + "lookup", + req, + reply_entry_to_desc_str + ) + } + + async fn getattr( + &self, + req: Request, + inode: Inode, + fh: Option<u64>, + flags: u32, + ) -> fuse3::Result<ReplyAttr> { + let filename = self.get_file_path_or_empty(inode).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "filename" = ?filename, + ?fh, + ?flags, + "GETATTR started" + ); + + log_value_custom!( + self.inner.getattr(req, inode, fh, flags), + "GETATTR", + req, + reply_attr_to_desc_str + ) + } + + async fn setattr( + &self, + req: Request, + inode: Inode, + fh: Option<u64>, + set_attr: SetAttr, + ) -> fuse3::Result<ReplyAttr> { + let filename = self.get_file_path_or_empty(inode).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "filename" = ?filename, + ?fh, + ?set_attr, + "SETATTR started" + ); + + log_value_custom!( + self.inner.setattr(req, inode, fh, set_attr), + "SETATTR", + req, + reply_attr_to_desc_str + ) + } + + async fn mkdir( + &self, + req: Request, + parent: Inode, + name: &OsStr, + mode: u32, + umask: u32, + ) -> fuse3::Result<ReplyEntry> { + let parent_path_name = self.get_file_path_or_empty(parent).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "parent" = ?parent_path_name, + "parent_id" = parent, + ?name, + mode, + umask, + "MKDIR started" + ); + + log_value_custom!( + self.inner.mkdir(req, parent, name, mode, umask), + "mkdir", + req, + reply_entry_to_desc_str + ) + } + + async fn unlink(&self, req: Request, parent: Inode, name: &OsStr) -> fuse3::Result<()> { + let parent_path_name = self.get_file_path_or_empty(parent).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "parent" = ?parent_path_name, + "parent_id" = parent, + ?name, + "UNLINK started" + ); + + log_status!(self.inner.unlink(req, parent, name), "unlink", req) + } + + async fn rmdir(&self, req: Request, parent: Inode, name: &OsStr) -> fuse3::Result<()> { + let parent_path_name = self.get_file_path_or_empty(parent).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + parent = ?parent_path_name, + ?name, + "RMDIR started" + ); + + log_status!(self.inner.rmdir(req, parent, name), "rmdir", req) + } + + async fn open(&self, req: Request, inode: Inode, flags: u32) -> fuse3::Result<ReplyOpen> { + let filename = self.get_file_path_or_empty(inode).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "filename" = ?filename, + "file_id" = inode, + ?flags, + "OPEN started" + ); + + log_value!(self.inner.open(req, inode, flags), "open", req) + } + + async fn read( + &self, + req: Request, + inode: Inode, + fh: u64, + offset: u64, + size: u32, + ) -> fuse3::Result<ReplyData> { + let filename = self.get_file_path_or_empty(inode).await; + debug!( + req.unique, + ?req, + "filename" = ?filename, + ?fh, + ?offset, + ?size, + "READ started" + ); + + log_status!(self.inner.read(req, inode, fh, offset, size), "read", req) + } + + async fn write( + &self, + req: Request, + inode: Inode, + fh: u64, + offset: u64, + data: &[u8], + write_flags: u32, + flags: u32, + ) -> fuse3::Result<ReplyWrite> { + let filename = self.get_file_path_or_empty(inode).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "filename" = ?filename, + "file_id" = inode, + ?fh, + ?offset, + data_len = data.len(), + ?write_flags, + ?flags, + "WRITE started" + ); + + log_status!( + self.inner + .write(req, inode, fh, offset, data, write_flags, flags), + "write", + req + ) + } + + async fn statfs(&self, req: Request, inode: Inode) -> fuse3::Result<ReplyStatFs> { + let filename = self.get_file_path_or_empty(inode).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "filename" = ?filename, + "file_id" = inode, + "STATFS started" + ); + + log_value!(self.inner.statfs(req, inode), "statfs", req) + } + + async fn release( + &self, + req: Request, + inode: Inode, + fh: u64, + flags: u32, + lock_owner: u64, + flush: bool, + ) -> fuse3::Result<()> { + let filename = self.get_file_path_or_empty(inode).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "filename" = ?filename, + "file_id" = inode, + ?fh, + ?flags, + ?lock_owner, + ?flush, + "RELEASE started" + ); + + log_status!( + self.inner.release(req, inode, fh, flags, lock_owner, flush), + "release", + req + ) + } + + async fn opendir(&self, req: Request, inode: Inode, flags: u32) -> fuse3::Result<ReplyOpen> { + let parent_path_name = self.get_file_path_or_empty(inode).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "dirname" = ?parent_path_name, + ?flags, + "OPENDIR started" + ); + + log_value!(self.inner.opendir(req, inode, flags), "opendir", req) + } + + type DirEntryStream<'a> + = BoxStream<'a, fuse3::Result<DirectoryEntry>> + where + T: 'a; + + #[allow(clippy::needless_lifetimes)] + async fn readdir<'a>( + &'a self, + req: Request, + parent: Inode, + fh: u64, + offset: i64, + ) -> fuse3::Result<ReplyDirectory<Self::DirEntryStream<'a>>> { + let parent_path_name = self.get_file_path_or_empty(parent).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "parent" = ?parent_path_name, + ?fh, + ?offset, + "READDIR started" + ); + + log_readdir!( + self.inner.readdir(req, parent, fh, offset), + "READDIR", + req, + directory_entry_to_desc_str, + ReplyDirectory + ) + } + + async fn releasedir( + &self, + req: Request, + inode: Inode, + fh: u64, + flags: u32, + ) -> fuse3::Result<()> { + let parent_path_name = self.get_file_path_or_empty(inode).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "dirname" = ?parent_path_name, + ?fh, + ?flags, + "RELEASEDIR started" + ); + + log_status!( + self.inner.releasedir(req, inode, fh, flags), + "releasedir", + req + ) + } + + async fn create( + &self, + req: Request, + parent: Inode, + name: &OsStr, + mode: u32, + flags: u32, + ) -> fuse3::Result<ReplyCreated> { + let parent_path_name = self.get_file_path_or_empty(parent).await; + + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "parent" = ?parent_path_name, + "parent_id" = parent, + "filename" = ?name, + ?mode, + ?flags, + "CREATE started" + ); + + log_value_custom!( + self.inner.create(req, parent, name, mode, flags), + "create", + req, + reply_created_to_desc_str + ) + } + + type DirEntryPlusStream<'a> = BoxStream<'a, fuse3::Result<DirectoryEntryPlus>> + where + T: 'a; + + #[allow(clippy::needless_lifetimes)] + async fn readdirplus<'a>( + &'a self, + req: Request, + parent: Inode, + fh: u64, + offset: u64, + lock_owner: u64, + ) -> fuse3::Result<ReplyDirectoryPlus<Self::DirEntryPlusStream<'a>>> { + let parent_path_name = self.get_file_path_or_empty(parent).await; + debug!( + req.unique, + "uid" = req.uid, + "gid" = req.gid, + "pid" = req.pid, + "parent" = ?parent_path_name, + ?fh, + ?offset, + ?lock_owner, + "READDIRPLUS started" + ); + + log_readdir!( + self.inner.readdirplus(req, parent, fh, offset, lock_owner), + "READDIRPLUS", + req, + directory_entry_plus_to_desc_str, + ReplyDirectoryPlus + ) + } +} diff --git a/clients/filesystem-fuse/src/fuse_server.rs b/clients/filesystem-fuse/src/fuse_server.rs index 0e8bd51833..fa4357e698 100644 --- a/clients/filesystem-fuse/src/fuse_server.rs +++ b/clients/filesystem-fuse/src/fuse_server.rs @@ -19,12 +19,12 @@ use crate::utils::GvfsResult; use fuse3::raw::{Filesystem, Session}; use fuse3::MountOptions; -use log::{error, info}; use std::path::Path; use std::process::exit; use std::sync::Arc; use tokio::select; use tokio::sync::Notify; +use tracing::{error, info}; /// Represents a FUSE server capable of starting and stopping the FUSE filesystem. pub struct FuseServer { diff --git a/clients/filesystem-fuse/src/gravitino_client.rs b/clients/filesystem-fuse/src/gravitino_client.rs index 1e1cd411ea..3e707d4958 100644 --- a/clients/filesystem-fuse/src/gravitino_client.rs +++ b/clients/filesystem-fuse/src/gravitino_client.rs @@ -202,6 +202,7 @@ impl GravitinoClient { pub(crate) mod tests { use super::*; use mockito::mock; + use tracing_subscriber::EnvFilter; pub(crate) fn create_test_catalog( name: &str, @@ -358,7 +359,10 @@ pub(crate) mod tests { } async fn get_fileset_example() { - tracing_subscriber::fmt::init(); + tracing_subscriber::fmt() + .with_env_filter(EnvFilter::from_default_env()) + .init(); + let config = GravitinoConfig { uri: "http://localhost:8090".to_string(), metalake: "test".to_string(), diff --git a/clients/filesystem-fuse/src/gvfs_fuse.rs b/clients/filesystem-fuse/src/gvfs_fuse.rs index 88079e99b9..4baf2170d7 100644 --- a/clients/filesystem-fuse/src/gvfs_fuse.rs +++ b/clients/filesystem-fuse/src/gvfs_fuse.rs @@ -21,15 +21,16 @@ use crate::default_raw_filesystem::DefaultRawFileSystem; use crate::error::ErrorCode::UnSupportedFilesystem; use crate::filesystem::FileSystemContext; use crate::fuse_api_handle::FuseApiHandle; +use crate::fuse_api_handle_debug::FuseApiHandleDebug; use crate::fuse_server::FuseServer; use crate::gravitino_fileset_filesystem::GravitinoFilesetFileSystem; use crate::gvfs_creator::create_gvfs_filesystem; use crate::memory_filesystem::MemoryFileSystem; use crate::utils::GvfsResult; -use log::info; use once_cell::sync::Lazy; use std::sync::Arc; use tokio::sync::Mutex; +use tracing::info; static SERVER: Lazy<Mutex<Option<Arc<FuseServer>>>> = Lazy::new(|| Mutex::new(None)); @@ -38,6 +39,8 @@ pub(crate) enum CreateFileSystemResult { Gvfs(GravitinoFilesetFileSystem), FuseMemoryFs(FuseApiHandle<DefaultRawFileSystem<MemoryFileSystem>>), FuseGvfs(FuseApiHandle<DefaultRawFileSystem<GravitinoFilesetFileSystem>>), + FuseMemoryFsWithDebug(FuseApiHandleDebug<DefaultRawFileSystem<MemoryFileSystem>>), + FuseGvfsWithDebug(FuseApiHandleDebug<DefaultRawFileSystem<GravitinoFilesetFileSystem>>), None, } @@ -56,7 +59,9 @@ pub async fn mount(mount_to: &str, mount_from: &str, config: &AppConfig) -> Gvfs let fs = create_fuse_fs(mount_from, config).await?; match fs { CreateFileSystemResult::FuseMemoryFs(vfs) => svr.start(vfs).await?, + CreateFileSystemResult::FuseMemoryFsWithDebug(vfs) => svr.start(vfs).await?, CreateFileSystemResult::FuseGvfs(vfs) => svr.start(vfs).await?, + CreateFileSystemResult::FuseGvfsWithDebug(vfs) => svr.start(vfs).await?, _ => return Err(UnSupportedFilesystem.to_error("Unsupported filesystem type".to_string())), } Ok(()) @@ -93,6 +98,14 @@ pub async fn create_raw_fs( ) -> GvfsResult<CreateFileSystemResult> { match path_fs { CreateFileSystemResult::Memory(fs) => { + if config.fuse.fuse_debug { + let fs = FuseApiHandleDebug::new( + DefaultRawFileSystem::new(fs, config, &fs_context), + config, + fs_context, + ); + return Ok(CreateFileSystemResult::FuseMemoryFsWithDebug(fs)); + } let fs = FuseApiHandle::new( DefaultRawFileSystem::new(fs, config, &fs_context), config, @@ -101,6 +114,14 @@ pub async fn create_raw_fs( Ok(CreateFileSystemResult::FuseMemoryFs(fs)) } CreateFileSystemResult::Gvfs(fs) => { + if config.fuse.fuse_debug { + let fs = FuseApiHandleDebug::new( + DefaultRawFileSystem::new(fs, config, &fs_context), + config, + fs_context, + ); + return Ok(CreateFileSystemResult::FuseGvfsWithDebug(fs)); + } let fs = FuseApiHandle::new( DefaultRawFileSystem::new(fs, config, &fs_context), config, diff --git a/clients/filesystem-fuse/src/lib.rs b/clients/filesystem-fuse/src/lib.rs index 65cd878f34..182fae3226 100644 --- a/clients/filesystem-fuse/src/lib.rs +++ b/clients/filesystem-fuse/src/lib.rs @@ -24,6 +24,7 @@ mod default_raw_filesystem; mod error; mod filesystem; mod fuse_api_handle; +mod fuse_api_handle_debug; mod fuse_server; mod gravitino_client; mod gravitino_fileset_filesystem; diff --git a/clients/filesystem-fuse/src/main.rs b/clients/filesystem-fuse/src/main.rs index 45fa26a827..a5ea723642 100644 --- a/clients/filesystem-fuse/src/main.rs +++ b/clients/filesystem-fuse/src/main.rs @@ -23,14 +23,18 @@ use clap::Parser; use daemonize::Daemonize; use gvfs_fuse::config::AppConfig; use gvfs_fuse::{gvfs_mount, gvfs_unmount, LOG_FILE_NAME, PID_FILE_NAME}; -use log::{error, info}; use std::fs::{create_dir, OpenOptions}; -use std::io; use std::path::Path; use std::process::Command; +use std::{env, io}; use tokio::runtime::Runtime; use tokio::signal; use tokio::signal::unix::{signal, SignalKind}; +use tracing::level_filters::LevelFilter; +use tracing::{error, info}; +use tracing_subscriber::fmt::Layer; +use tracing_subscriber::layer::Layered; +use tracing_subscriber::{filter, fmt, prelude::*, reload, EnvFilter, Registry}; fn init_dirs(config: &mut AppConfig, mount_point: &str) -> io::Result<()> { let data_dir_name = Path::new(&config.fuse.data_dir).to_path_buf(); @@ -165,15 +169,36 @@ fn do_umount(_mp: &str, _force: bool) -> std::io::Result<()> { )) } +/// init tracing subscriber with directives, and returns reload handle to allow us to modify filter dynamically. +fn init_tracing_subscriber( + directives: &str, +) -> reload::Handle<EnvFilter, Layered<Layer<Registry>, Registry>> { + let env_filter = EnvFilter::builder() + .with_default_directive(LevelFilter::INFO.into()) + .parse(directives) + .unwrap(); + + let (filter, reload_handle) = reload::Layer::new(env_filter); + + // Initialize the subscriber + tracing_subscriber::registry() + .with(fmt::layer()) + .with(filter) + .init(); + + reload_handle +} + fn main() -> Result<(), i32> { - tracing_subscriber::fmt().init(); + let directives = env::var("RUST_LOG").unwrap_or("".to_string()); let args = command_args::Arguments::parse(); + let reload_handle = init_tracing_subscriber(directives.as_str()); match args.command { Commands::Mount { mount_point, fileset_location, config, - debug: _, + debug: debug_level, foreground, } => { let app_config = AppConfig::from_file(config); @@ -193,6 +218,28 @@ fn main() -> Result<(), i32> { path.to_string_lossy().to_string() }; + // if debug > 0, it means that we needs fuse_debug. + app_config.fuse.fuse_debug = debug_level > 0 || app_config.fuse.fuse_debug; + match debug_level { + 0 => { + // Use the value in RUST_LOG, no need to modify filter + } + 1 => { + // debug feature of gvfs_fuse is enabled. + reload_handle + .modify(|filter| { + *filter = filter::EnvFilter::builder() + .parse([directives.as_str(), "gvfs_fuse=debug"].join(",").as_str()) + .unwrap(); + }) + .unwrap(); + } + _ => { + error!("Unsupported debug level: {}", debug_level); + return Err(-1); + } + } + let result = init_dirs(&mut app_config, &mount_point); if let Err(e) = result { error!("Failed to initialize working directories: {:?}", e); @@ -203,6 +250,7 @@ fn main() -> Result<(), i32> { mount_fuse(app_config, mount_point, fileset_location) } else { let result = make_daemon(&app_config); + info!("Making daemon"); if let Err(e) = result { error!("Failed to daemonize: {:?}", e); return Err(-1); diff --git a/clients/filesystem-fuse/src/open_dal_filesystem.rs b/clients/filesystem-fuse/src/open_dal_filesystem.rs index 01969d74e0..b4ae6e433c 100644 --- a/clients/filesystem-fuse/src/open_dal_filesystem.rs +++ b/clients/filesystem-fuse/src/open_dal_filesystem.rs @@ -25,11 +25,11 @@ use async_trait::async_trait; use bytes::Bytes; use fuse3::FileType::{Directory, RegularFile}; use fuse3::{Errno, FileType, Timestamp}; -use log::error; use opendal::{Buffer, EntryMode, ErrorKind, Metadata, Operator}; use std::mem::swap; use std::path::{Path, PathBuf}; use std::time::SystemTime; +use tracing::error; pub(crate) struct OpenDalFileSystem { op: Operator, diff --git a/clients/filesystem-fuse/src/s3_filesystem.rs b/clients/filesystem-fuse/src/s3_filesystem.rs index f4e9fd440d..c3e94155d6 100644 --- a/clients/filesystem-fuse/src/s3_filesystem.rs +++ b/clients/filesystem-fuse/src/s3_filesystem.rs @@ -25,12 +25,12 @@ use crate::opened_file::{OpenFileFlags, OpenedFile}; use crate::utils::{parse_location, GvfsResult}; use async_trait::async_trait; use fuse3::FileType; -use log::error; use opendal::layers::LoggingLayer; use opendal::services::S3; use opendal::{Builder, Operator}; use std::collections::HashMap; use std::path::Path; +use tracing::error; pub(crate) struct S3FileSystem { open_dal_fs: OpenDalFileSystem, diff --git a/clients/filesystem-fuse/tests/conf/gvfs_fuse_memory.toml b/clients/filesystem-fuse/tests/conf/gvfs_fuse_memory.toml index 0ec447cd08..c6eb0109a1 100644 --- a/clients/filesystem-fuse/tests/conf/gvfs_fuse_memory.toml +++ b/clients/filesystem-fuse/tests/conf/gvfs_fuse_memory.toml @@ -20,6 +20,7 @@ file_mask= 0o600 dir_mask= 0o700 fs_type = "memory" +fuse_debug = true [fuse.properties] key1 = "value1" diff --git a/clients/filesystem-fuse/tests/fuse_test.rs b/clients/filesystem-fuse/tests/fuse_test.rs index cd7dbf7ea9..0315290fdb 100644 --- a/clients/filesystem-fuse/tests/fuse_test.rs +++ b/clients/filesystem-fuse/tests/fuse_test.rs @@ -21,7 +21,6 @@ use fuse3::Errno; use gvfs_fuse::config::AppConfig; use gvfs_fuse::RUN_TEST_WITH_FUSE; use gvfs_fuse::{gvfs_mount, gvfs_unmount, test_enable_with}; -use log::{error, info}; use once_cell::sync::Lazy; use std::collections::HashSet; use std::fs::{File, OpenOptions}; @@ -32,6 +31,8 @@ use std::{env, fs}; use tokio::runtime::Runtime; use tokio::task::JoinHandle; use tokio::time::interval; +use tracing::{error, info}; +use tracing_subscriber::EnvFilter; static ASYNC_RUNTIME: Lazy<Runtime> = Lazy::new(|| Runtime::new().unwrap()); @@ -472,7 +473,9 @@ fn test_manually() { #[test] fn fuse_it_test_fuse() { test_enable_with!(RUN_TEST_WITH_FUSE); - tracing_subscriber::fmt().init(); + tracing_subscriber::fmt() + .with_env_filter(EnvFilter::from_default_env()) + .init(); let mount_point = Path::new("target/gvfs"); let test_dir = mount_point.join("test_dir"); @@ -482,7 +485,9 @@ fn fuse_it_test_fuse() { #[test] fn test_fuse_with_memory_fs() { - tracing_subscriber::fmt().init(); + tracing_subscriber::fmt() + .with_env_filter(EnvFilter::from_default_env()) + .init(); let mount_point = "target/gvfs"; let _ = fs::create_dir_all(mount_point);