From d2317a509a253228982ce385c3584b497156c679 Mon Sep 17 00:00:00 2001 From: Jonathan Woollett-Light Date: Wed, 18 Oct 2023 12:35:05 +0100 Subject: [PATCH 1/5] docs: Remove `log_path` as required `log_path` is no longer required by the `/logger` API. Removes `log_path` from `required:` in the `firecracker.yaml` swagger specification for the API. Signed-off-by: Jonathan Woollett-LIght --- src/api_server/swagger/firecracker.yaml | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/api_server/swagger/firecracker.yaml b/src/api_server/swagger/firecracker.yaml index bd167a4c5a1..296da813dc3 100644 --- a/src/api_server/swagger/firecracker.yaml +++ b/src/api_server/swagger/firecracker.yaml @@ -977,8 +977,6 @@ definitions: type: object description: Describes the configuration option for the logging capability. - required: - - log_path properties: level: type: string From 91437af74ceab77aadd7ebbd76a42f24a103fb4d Mon Sep 17 00:00:00 2001 From: Jonathan Woollett-Light Date: Fri, 20 Oct 2023 15:08:52 +0100 Subject: [PATCH 2/5] feat(logger): Add module filter Adds a module filter to the logger. This allows a user at runtime to filter log messages by the Rust source code crate and module from which they originate. Signed-off-by: Jonathan Woollett-Light --- src/api_server/src/request/logger.rs | 2 ++ src/api_server/swagger/firecracker.yaml | 3 ++ src/firecracker/src/main.rs | 7 +++++ src/vmm/src/logger/logging.rs | 40 +++++++++++++++++++------ src/vmm/src/rpc_interface.rs | 1 + 5 files changed, 44 insertions(+), 9 deletions(-) diff --git a/src/api_server/src/request/logger.rs b/src/api_server/src/request/logger.rs index ad16246bc14..67fb37a3926 100644 --- a/src/api_server/src/request/logger.rs +++ b/src/api_server/src/request/logger.rs @@ -40,6 +40,7 @@ mod tests { level: Some(LevelFilter::Warn), show_level: Some(false), show_log_origin: Some(false), + module: None, }; assert_eq!( vmm_action_from_request(parse_put_logger(&Body::new(body)).unwrap()), @@ -58,6 +59,7 @@ mod tests { level: Some(LevelFilter::Debug), show_level: Some(false), show_log_origin: Some(false), + module: None, }; assert_eq!( vmm_action_from_request(parse_put_logger(&Body::new(body)).unwrap()), diff --git a/src/api_server/swagger/firecracker.yaml b/src/api_server/swagger/firecracker.yaml index 296da813dc3..0d8bb5ad0db 100644 --- a/src/api_server/swagger/firecracker.yaml +++ b/src/api_server/swagger/firecracker.yaml @@ -994,6 +994,9 @@ definitions: type: boolean description: Whether or not to include the file path and line number of the log's origin. default: false + module: + type: string + description: The module path to filter log messages by. MachineConfiguration: type: object diff --git a/src/firecracker/src/main.rs b/src/firecracker/src/main.rs index b41f3739911..ef1421e92c3 100644 --- a/src/firecracker/src/main.rs +++ b/src/firecracker/src/main.rs @@ -207,6 +207,11 @@ fn main_exec() -> Result<(), MainError> { .takes_value(true) .help("Set the logger level."), ) + .arg( + Argument::new("module") + .takes_value(true) + .help("Set the logger module filter."), + ) .arg( Argument::new("show-level") .takes_value(false) @@ -280,12 +285,14 @@ fn main_exec() -> Result<(), MainError> { .map_err(MainError::InvalidLogLevel)?; let show_level = arguments.flag_present("show-level").then_some(true); let show_log_origin = arguments.flag_present("show-log-origin").then_some(true); + let module = arguments.single_value("module").cloned(); LOGGER .update(LoggerConfig { log_path, level, show_level, show_log_origin, + module, }) .map_err(MainError::LoggerInitialization)?; info!("Running Firecracker v{FIRECRACKER_VERSION}"); diff --git a/src/vmm/src/logger/logging.rs b/src/vmm/src/logger/logging.rs index 58177a84ffb..7f45e4d2499 100644 --- a/src/vmm/src/logger/logging.rs +++ b/src/vmm/src/logger/logging.rs @@ -28,6 +28,7 @@ pub static INSTANCE_ID: OnceLock = OnceLock::new(); /// Default values matching the swagger specification (`src/api_server/swagger/firecracker.yaml`). pub static LOGGER: Logger = Logger(Mutex::new(LoggerConfiguration { target: None, + filter: LogFilter { module: None }, format: LogFormat { show_level: false, show_log_origin: false, @@ -79,6 +80,10 @@ impl Logger { guard.format.show_log_origin = show_log_origin; } + if let Some(module) = config.module { + guard.filter.module = Some(module); + } + // Ensure we drop the guard before attempting to log, otherwise this // would deadlock. drop(guard); @@ -87,6 +92,10 @@ impl Logger { } } +#[derive(Debug)] +pub struct LogFilter { + pub module: Option, +} #[derive(Debug)] pub struct LogFormat { pub show_level: bool, @@ -95,6 +104,7 @@ pub struct LogFormat { #[derive(Debug)] pub struct LoggerConfiguration { pub target: Option, + pub filter: LogFilter, pub format: LogFormat, } #[derive(Debug)] @@ -110,6 +120,19 @@ impl Log for Logger { // Lock the logger. let mut guard = self.0.lock().unwrap(); + // Check if the log message is enabled + { + let enabled_module = match (&guard.filter.module, record.module_path()) { + (Some(filter), Some(source)) => source.starts_with(filter), + (Some(_), None) => false, + (None, _) => true, + }; + let enabled = enabled_module; + if !enabled { + return; + } + } + // Prints log message { let thread = thread::current().name().unwrap_or("-").to_string(); @@ -154,10 +177,7 @@ impl Log for Logger { } } - // This is currently not used. - fn flush(&self) { - unreachable!(); - } + fn flush(&self) {} } /// Strongly typed structure used to describe the logger. @@ -172,6 +192,8 @@ pub struct LoggerConfig { pub show_level: Option, /// Whether to show the log origin in the log. pub show_log_origin: Option, + /// The module to filter logs by. + pub module: Option, } /// This is required since we originally supported `Warning` and uppercase variants being used as @@ -307,6 +329,9 @@ mod tests { // Create logger. let logger = Logger(Mutex::new(LoggerConfiguration { target: Some(target), + filter: LogFilter { + module: Some(String::from("module")), + }, format: LogFormat { show_level: true, show_log_origin: true, @@ -328,11 +353,8 @@ mod tests { .build(); logger.log(&record); - // Assert calling flush panics. - std::panic::catch_unwind(|| { - logger.flush(); - }) - .unwrap_err(); + // Test calling flush. + logger.flush(); // Asserts result of log. let contents = std::fs::read_to_string(&path).unwrap(); diff --git a/src/vmm/src/rpc_interface.rs b/src/vmm/src/rpc_interface.rs index 67482f5d5ba..5df04be4607 100644 --- a/src/vmm/src/rpc_interface.rs +++ b/src/vmm/src/rpc_interface.rs @@ -2025,6 +2025,7 @@ mod tests { level: Some(crate::logger::LevelFilter::Debug), show_level: Some(false), show_log_origin: Some(false), + module: None, }), VmmActionError::OperationNotSupportedPostBoot, ); From 040c7028ae32664e9de8a7bd3c9167e85c52ce09 Mon Sep 17 00:00:00 2001 From: Jonathan Woollett-Light Date: Mon, 6 Nov 2023 07:43:09 +0000 Subject: [PATCH 3/5] feat: Instrumentation tooling Adds a crate (`log-instrument`) with an instrumentation macro. Adds a binary (`clippy-tracing`) to add, remove and check for instrumentation. Signed-off-by: Jonathan Woollett-Light --- Cargo.lock | 123 ++++- Cargo.toml | 2 +- src/api_server/Cargo.toml | 4 + src/api_server/swagger/firecracker.yaml | 1 + src/clippy-tracing/Cargo.toml | 21 + src/clippy-tracing/README.md | 85 +++ src/clippy-tracing/src/main.rs | 447 ++++++++++++++++ src/clippy-tracing/tests/integration_tests.rs | 489 ++++++++++++++++++ src/cpu-template-helper/Cargo.toml | 4 + src/firecracker/Cargo.toml | 4 + src/jailer/Cargo.toml | 4 + src/log-instrument-macros/Cargo.toml | 16 + src/log-instrument-macros/src/lib.rs | 38 ++ src/log-instrument/Cargo.toml | 39 ++ src/log-instrument/README.md | 58 +++ src/log-instrument/src/bin/five.rs | 32 ++ src/log-instrument/src/bin/four.rs | 28 + src/log-instrument/src/bin/one.rs | 22 + src/log-instrument/src/bin/six.rs | 28 + src/log-instrument/src/bin/three.rs | 25 + src/log-instrument/src/bin/two.rs | 25 + src/log-instrument/src/lib.rs | 56 ++ src/log-instrument/tests/integration_tests.rs | 148 ++++++ src/rebase-snap/Cargo.toml | 4 + src/seccompiler/Cargo.toml | 4 + src/snapshot-editor/Cargo.toml | 4 + src/snapshot/Cargo.toml | 4 + src/utils/Cargo.toml | 4 + src/vmm/Cargo.toml | 4 + 29 files changed, 1704 insertions(+), 19 deletions(-) create mode 100644 src/clippy-tracing/Cargo.toml create mode 100644 src/clippy-tracing/README.md create mode 100644 src/clippy-tracing/src/main.rs create mode 100644 src/clippy-tracing/tests/integration_tests.rs create mode 100644 src/log-instrument-macros/Cargo.toml create mode 100644 src/log-instrument-macros/src/lib.rs create mode 100644 src/log-instrument/Cargo.toml create mode 100644 src/log-instrument/README.md create mode 100644 src/log-instrument/src/bin/five.rs create mode 100644 src/log-instrument/src/bin/four.rs create mode 100644 src/log-instrument/src/bin/one.rs create mode 100644 src/log-instrument/src/bin/six.rs create mode 100644 src/log-instrument/src/bin/three.rs create mode 100644 src/log-instrument/src/bin/two.rs create mode 100644 src/log-instrument/src/lib.rs create mode 100644 src/log-instrument/tests/integration_tests.rs diff --git a/Cargo.lock b/Cargo.lock index 1ddffec58d1..54464deb309 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -106,6 +106,7 @@ version = "0.1.0" dependencies = [ "displaydoc", "libc", + "log-instrument", "micro_http", "seccompiler", "serde", @@ -168,7 +169,7 @@ version = "0.68.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "726e4313eb6ec35d2730258ad4e15b547ee75d6afaa1361a922e78e59b7d8078" dependencies = [ - "bitflags 2.4.0", + "bitflags 2.4.1", "cexpr", "clang-sys", "lazy_static", @@ -193,9 +194,9 @@ checksum = "bef38d45163c2f1dde094a7dfd33ccf595c92905c8f8f4fdc18d06fb1037718a" [[package]] name = "bitflags" -version = "2.4.0" +version = "2.4.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b4682ae6287fcf752ecaabbfcc7b6f9b72aa33933dc23a554d853aea8eea8635" +checksum = "327762f6e5a765692301e5bb513e0d9fef63be86bbc14528052b1cd3e6f03e07" [[package]] name = "cargo_toml" @@ -334,6 +335,19 @@ version = "0.6.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "702fc72eb24e5a1e48ce58027a675bc24edd52096d5397d4aea7c6dd9eca0bd1" +[[package]] +name = "clippy-tracing" +version = "0.1.0" +dependencies = [ + "clap", + "itertools 0.11.0", + "proc-macro2", + "quote", + "syn 2.0.38", + "uuid", + "walkdir", +] + [[package]] name = "cmake" version = "0.1.50" @@ -356,6 +370,7 @@ dependencies = [ "clap", "displaydoc", "libc", + "log-instrument", "serde", "serde_json", "thiserror", @@ -390,7 +405,7 @@ dependencies = [ "clap", "criterion-plot", "is-terminal", - "itertools", + "itertools 0.10.5", "num-traits", "once_cell", "oorandom", @@ -409,7 +424,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6b50826342786a51a89e2da3a28f1c32b06e387201bc2d19791f622c673706b1" dependencies = [ "cast", - "itertools", + "itertools 0.10.5", ] [[package]] @@ -471,6 +486,19 @@ version = "1.9.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a26ae43d7bcc3b814de94796a5e736d4029efb0ee900c12e2d54c993ad1a1e07" +[[package]] +name = "env_logger" +version = "0.10.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "85cdab6a89accf66733ad5a1693a4dcced6aeff64602b634530dd73c1f3ee9f0" +dependencies = [ + "humantime", + "is-terminal", + "log", + "regex", + "termcolor", +] + [[package]] name = "equivalent" version = "1.0.1" @@ -507,6 +535,7 @@ dependencies = [ "displaydoc", "event-manager", "libc", + "log-instrument", "regex", "seccompiler", "serde", @@ -589,6 +618,12 @@ dependencies = [ "windows-sys", ] +[[package]] +name = "humantime" +version = "2.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" + [[package]] name = "indexmap" version = "2.0.2" @@ -626,7 +661,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cb0889898416213fab133e1d33a0e5858a48177452750691bde3666d0fdbaf8b" dependencies = [ "hermit-abi", - "rustix 0.38.17", + "rustix 0.38.20", "windows-sys", ] @@ -639,6 +674,15 @@ dependencies = [ "either", ] +[[package]] +name = "itertools" +version = "0.11.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b1c173a5686ce8bfa551b3563d0c2170bf24ca44da99c7ca4bfdab5418c3fe57" +dependencies = [ + "either", +] + [[package]] name = "itoa" version = "1.0.9" @@ -650,6 +694,7 @@ name = "jailer" version = "1.6.0-dev" dependencies = [ "libc", + "log-instrument", "nix", "regex", "thiserror", @@ -728,9 +773,9 @@ checksum = "ef53942eb7bf7ff43a617b3e2c1c4a5ecf5944a7c1bc12d7ee39bbb15e5c1519" [[package]] name = "linux-raw-sys" -version = "0.4.8" +version = "0.4.10" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3852614a3bd9ca9804678ba6be5e3b8ce76dfc902cae004e3e0c44051b6e88db" +checksum = "da2479e8c062e40bf0066ffa0bc823de0a9368974af99c9f6df941d2c231e03f" [[package]] name = "log" @@ -741,6 +786,24 @@ dependencies = [ "serde", ] +[[package]] +name = "log-instrument" +version = "0.3.0" +dependencies = [ + "env_logger", + "log", + "log-instrument-macros", +] + +[[package]] +name = "log-instrument-macros" +version = "0.1.0" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.38", +] + [[package]] name = "memchr" version = "2.6.4" @@ -753,7 +816,7 @@ version = "0.6.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b2cffa4ad52c6f791f4f8b15f0c05f9824b2ced1160e88cc393d64fff9a8ac64" dependencies = [ - "rustix 0.38.17", + "rustix 0.38.20", ] [[package]] @@ -783,7 +846,7 @@ version = "0.27.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2eb04e9c688eff1c89d72b407f168cf79bb9e867a9d3323ed6c01519eb9cc053" dependencies = [ - "bitflags 2.4.0", + "bitflags 2.4.1", "cfg-if", "libc", ] @@ -881,7 +944,7 @@ version = "1.3.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7c003ac8c77cb07bb74f5f198bce836a689bcd5a42574612bf14d17bfd08c20e" dependencies = [ - "bitflags 2.4.0", + "bitflags 2.4.1", "lazy_static", "num-traits", "rand", @@ -945,6 +1008,7 @@ version = "1.6.0-dev" dependencies = [ "displaydoc", "libc", + "log-instrument", "thiserror", "utils", ] @@ -1006,14 +1070,14 @@ dependencies = [ [[package]] name = "rustix" -version = "0.38.17" +version = "0.38.20" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f25469e9ae0f3d0047ca8b93fc56843f38e6774f0914a107ff8b41be8be8e0b7" +checksum = "67ce50cb2e16c2903e30d1cbccfd8387a74b9d4c938b6a4c5ec6cc7556f7a8a0" dependencies = [ - "bitflags 2.4.0", + "bitflags 2.4.1", "errno", "libc", - "linux-raw-sys 0.4.8", + "linux-raw-sys 0.4.10", "windows-sys", ] @@ -1039,6 +1103,7 @@ dependencies = [ "bincode", "displaydoc", "libc", + "log-instrument", "serde", "serde_json", "thiserror", @@ -1107,6 +1172,7 @@ dependencies = [ "criterion", "displaydoc", "libc", + "log-instrument", "thiserror", "versionize", "versionize_derive", @@ -1120,6 +1186,7 @@ dependencies = [ "clap-num", "displaydoc", "libc", + "log-instrument", "snapshot", "thiserror", "utils", @@ -1160,6 +1227,15 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "termcolor" +version = "1.3.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6093bad37da69aab9d123a8091e4be0aa4a03e4d601ec641c327398315f62b64" +dependencies = [ + "winapi-util", +] + [[package]] name = "thiserror" version = "1.0.50" @@ -1273,7 +1349,7 @@ version = "0.7.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b6a38c7e24af201e66f02659492f86ccd5efa9fd62f2c851fff3961a60e81966" dependencies = [ - "bitflags 2.4.0", + "bitflags 2.4.1", "cfg-if", "libc", "nix", @@ -1305,6 +1381,7 @@ dependencies = [ "derive_more", "displaydoc", "libc", + "log-instrument", "serde", "serde_json", "thiserror", @@ -1314,6 +1391,15 @@ dependencies = [ "vmm-sys-util", ] +[[package]] +name = "uuid" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "88ad59a7560b41a70d191093a945f0b87bc1deeda46fb237479708a1d6b6cdfc" +dependencies = [ + "getrandom", +] + [[package]] name = "version_check" version = "0.9.4" @@ -1389,7 +1475,7 @@ dependencies = [ "aws-lc-rs", "base64", "bincode", - "bitflags 2.4.0", + "bitflags 2.4.1", "criterion", "derive_more", "device_tree", @@ -1401,6 +1487,7 @@ dependencies = [ "libc", "linux-loader", "log", + "log-instrument", "memfd", "micro_http", "proptest", @@ -1456,7 +1543,7 @@ dependencies = [ "either", "home", "once_cell", - "rustix 0.38.17", + "rustix 0.38.20", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index f0ab0cb0cee..a4b903e5734 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,5 +1,5 @@ [workspace] -members = ["src/cpu-template-helper", "src/firecracker", "src/jailer", "src/rebase-snap", "src/seccompiler", "src/snapshot-editor"] +members = ["src/clippy-tracing", "src/cpu-template-helper", "src/firecracker", "src/jailer", "src/log-instrument", "src/log-instrument-macros", "src/rebase-snap", "src/seccompiler", "src/snapshot-editor"] default-members = ["src/firecracker"] resolver = "2" diff --git a/src/api_server/Cargo.toml b/src/api_server/Cargo.toml index a786df5ae9e..8d735d293a2 100644 --- a/src/api_server/Cargo.toml +++ b/src/api_server/Cargo.toml @@ -15,6 +15,7 @@ serde_derive = "1.0.136" serde_json = "1.0.78" thiserror = "1.0.32" displaydoc = "0.2.4" +log-instrument = { path = "../log-instrument", optional = true } micro_http = { git = "https://github.com/firecracker-microvm/micro-http" } seccompiler = { path = "../seccompiler" } @@ -23,3 +24,6 @@ vmm = { path = "../vmm" } [dev-dependencies] libc = "0.2.117" + +[features] +tracing = ["log-instrument"] diff --git a/src/api_server/swagger/firecracker.yaml b/src/api_server/swagger/firecracker.yaml index 0d8bb5ad0db..3b0760b1b27 100644 --- a/src/api_server/swagger/firecracker.yaml +++ b/src/api_server/swagger/firecracker.yaml @@ -997,6 +997,7 @@ definitions: module: type: string description: The module path to filter log messages by. + example: api_server::request MachineConfiguration: type: object diff --git a/src/clippy-tracing/Cargo.toml b/src/clippy-tracing/Cargo.toml new file mode 100644 index 00000000000..1fe6c4ef6c2 --- /dev/null +++ b/src/clippy-tracing/Cargo.toml @@ -0,0 +1,21 @@ +[package] +name = "clippy-tracing" +version = "0.1.0" +authors = ["Amazon Firecracker team "] +edition = "2021" +license = "Apache-2.0" + +[[bin]] +name = "clippy-tracing" +bench = false + +[dependencies] +clap = { version = "4.3.2", features = ["derive"] } +itertools = "0.11.0" +proc-macro2 = { version = "1.0.63", features = ["span-locations"] } +quote = "1.0.28" +syn = { version = "2.0.17", features = ["full", "extra-traits", "visit", "visit-mut", "printing"] } +walkdir = "2.3.3" + +[dev-dependencies] +uuid = { version = "1.4.1", features = ["v4"] } diff --git a/src/clippy-tracing/README.md b/src/clippy-tracing/README.md new file mode 100644 index 00000000000..8327302b481 --- /dev/null +++ b/src/clippy-tracing/README.md @@ -0,0 +1,85 @@ +# clippy-tracing + +A tool to add, remove and check for `log_instrument::instrument` +in large projects where it is infeasible to manually add it to thousands +of functions. + +## Usage + +This is tested in the +[`readme()` integration test](../clippy-tracing/tests/integration_tests.rs) +. + +```rust +fn main() { + println!("Hello World!"); +} +fn add(lhs: i32, rhs: i32) -> i32 { + lhs + rhs +} +#[cfg(tests)] +mod tests { + fn sub(lhs: i32, rhs: i32) -> i32 { + lhs - rhs + } + #[test] + fn test_one() { + assert_eq!(add(1,1), sub(2, 1)); + } +} +``` + +```bash +clippy-tracing --action check # Missing instrumentation at {path}:9:4.\n +echo $? # 2 +clippy-tracing --action fix +echo $? # 0 +``` + +```rust +#[log_instrument::instrument(level = "trace", skip())] +fn main() { + println!("Hello World!"); +} +#[log_instrument::instrument(level = "trace", skip(lhs, rhs))] +fn add(lhs: i32, rhs: i32) -> i32 { + lhs + rhs +} +#[cfg(tests)] +mod tests { + #[log_instrument::instrument(level = "trace", skip(lhs, rhs))] + fn sub(lhs: i32, rhs: i32) -> i32 { + lhs - rhs + } + #[test] + fn test_one() { + assert_eq!(add(1,1), sub(2, 1)); + } +} +``` + +```bash +clippy-tracing --action check +echo $? # 0 +clippy-tracing --action strip +echo $? # 0 +``` + +```rust +fn main() { + println!("Hello World!"); +} +fn add(lhs: i32, rhs: i32) -> i32 { + lhs + rhs +} +#[cfg(tests)] +mod tests { + fn sub(lhs: i32, rhs: i32) -> i32 { + lhs - rhs + } + #[test] + fn test_one() { + assert_eq!(add(1,1), sub(2, 1)); + } +} +``` diff --git a/src/clippy-tracing/src/main.rs b/src/clippy-tracing/src/main.rs new file mode 100644 index 00000000000..61de2eee148 --- /dev/null +++ b/src/clippy-tracing/src/main.rs @@ -0,0 +1,447 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +#![warn(clippy::pedantic)] + +//! A tool to add, remove and check for `tracing::instrument` in large projects where it is +//! infeasible to manually add it to thousands of functions. + +use std::collections::HashMap; +use std::error::Error; +use std::fmt; +use std::fs::OpenOptions; +use std::io::{Read, Write}; +use std::path::PathBuf; +use std::process::ExitCode; + +use clap::{Parser, ValueEnum}; +use syn::spanned::Spanned; +use syn::visit::Visit; +use walkdir::WalkDir; + +/// The command line arguments for the application. +#[derive(Parser)] +struct CommandLineArgs { + /// The action to take. + #[arg(long)] + action: Action, + /// The path to look in. + #[arg(long)] + path: Option, + /// When adding instrumentation use a custom suffix e.g. + /// `--suffix my::custom::suffix::`. + /// + /// The tool may be unable to strip instrumentation with an invalid suffix. + #[arg(long)] + suffix: Option, + /// Whether to add a `cfg_attr` condition e.g. + /// `#[cfg_attr(feature = "tracing", log_instrument::instrument)]` vs + /// `#[log_instrument::instrument]`. + #[arg(long)] + cfg_attr: Option, + /// Sub-paths which contain any of the strings from this list will be ignored. + #[arg(long, value_delimiter = ',')] + exclude: Vec, +} + +/// The action to take. +#[derive(Clone, ValueEnum)] +enum Action { + /// Checks `tracing::instrument` is on all functions. + Check, + /// Adds `tracing::instrument` to all functions. + Fix, + /// Removes `tracing::instrument` from all functions. + Strip, +} + +/// A list of text lines split so that newlines can be efficiently inserted between them. +struct SegmentedList { + /// The first new line. + first: String, + /// The inner vector used to contain the original lines `.0` and the new lines `.1`. + inner: Vec<(String, String)>, +} +impl SegmentedList { + /// Sets the text line before `line` to `text`. + fn set_before(&mut self, line: usize, text: String) -> bool { + let s = if let Some(i) = line.checked_sub(1) { + let Some(mut_ref) = self.inner.get_mut(i) else { + return false; + }; + &mut mut_ref.1 + } else { + &mut self.first + }; + *s = text; + true + } +} +impl From for String { + fn from(list: SegmentedList) -> String { + let iter = list + .inner + .into_iter() + .map(|(x, y)| format!("{x}{}{y}", if y.is_empty() { "" } else { "\n" })); + format!( + "{}{}{}", + list.first, + if list.first.is_empty() { "" } else { "\n" }, + itertools::intersperse(iter, String::from("\n")).collect::() + ) + } +} + +/// Visitor for the `strip` action. +struct StripVisitor(HashMap); +impl From for String { + fn from(visitor: StripVisitor) -> String { + let mut vec = visitor.0.into_iter().collect::>(); + vec.sort_by_key(|(i, _)| *i); + itertools::intersperse(vec.into_iter().map(|(_, x)| x), String::from("\n")) + .collect::() + } +} + +macro_rules! create_strip_visitor_function { + ($func_name:ident, $item:ident) => { + fn $func_name(&mut self, i: &syn::$item) { + if let Some(instrument) = find_instrumented(&i.attrs) { + let start = instrument.span().start().line - 1; + let end = instrument.span().end().line; + for line in start..end { + self.0.remove(&line); + } + } + self.visit_block(&i.block); + } + }; +} + +impl syn::visit::Visit<'_> for StripVisitor { + create_strip_visitor_function!(visit_impl_item_fn, ImplItemFn); + create_strip_visitor_function!(visit_item_fn, ItemFn); +} + +/// Visitor for the `check` action. +struct CheckVisitor(Option); + +macro_rules! create_check_visitor_function { + ($func_name:ident, $item:ident) => { + fn $func_name(&mut self, i: &syn::$item) { + let attr = check_attributes(&i.attrs); + if !attr.instrumented && !attr.test && i.sig.constness.is_none() { + self.0 = Some(i.span()); + } else { + self.visit_block(&i.block); + } + } + }; +} + +impl syn::visit::Visit<'_> for CheckVisitor { + create_check_visitor_function!(visit_impl_item_fn, ImplItemFn); + create_check_visitor_function!(visit_item_fn, ItemFn); +} + +/// Visitor for the `fix` action. +struct FixVisitor<'a> { + /// A custom path suffix. + suffix: &'a Option, + /// A `cfg_attr` condition. + cfg_attr: &'a Option, + /// Source + list: SegmentedList, +} +impl From> for String { + fn from(visitor: FixVisitor) -> String { + String::from(visitor.list) + } +} + +macro_rules! create_fix_visitor_function { + ($func_name:ident, $item:ident) => { + fn $func_name(&mut self, i: &syn::$item) { + let attr = check_attributes(&i.attrs); + + if !attr.instrumented && !attr.test && i.sig.constness.is_none() { + let line = i.span().start().line; + + let attr_string = instrument(&i.sig, self.suffix, self.cfg_attr); + let indent = i.span().start().column; + let indent_attr = format!("{}{attr_string}", " ".repeat(indent)); + self.list.set_before(line - 1, indent_attr); + } + self.visit_block(&i.block); + } + }; +} + +impl syn::visit::Visit<'_> for FixVisitor<'_> { + create_fix_visitor_function!(visit_impl_item_fn, ImplItemFn); + create_fix_visitor_function!(visit_item_fn, ItemFn); +} + +fn instrument(sig: &syn::Signature, suffix: &Option, cfg_attr: &Option) -> String { + let instr = inner_instrument(sig, suffix); + if let Some(cfg_attr) = cfg_attr { + format!("#[cfg_attr({cfg_attr}, {instr})]") + } else { + format!("#[{instr}]") + } +} + +/// Returns the instrument macro for a given function signature. +fn inner_instrument(_sig: &syn::Signature, suffix: &Option) -> String { + format!( + "{}instrument", + suffix.as_ref().map_or("log_instrument::", String::as_str) + ) +} + +/// Type to return from `main` to support returning an error then handling it. +#[repr(u8)] +enum Exit { + /// Process completed successfully. + Ok = 0, + /// Process encountered an error. + Error = 1, + /// Process ran `check` action and found missing instrumentation. + Check = 2, +} +#[allow(clippy::as_conversions)] +impl std::process::Termination for Exit { + fn report(self) -> ExitCode { + ExitCode::from(self as u8) + } +} + +fn main() -> Exit { + match exec() { + Err(err) => { + eprintln!("Error: {err}"); + Exit::Error + } + Ok(None) => Exit::Ok, + Ok(Some((path, line, column))) => { + println!( + "Missing instrumentation at {}:{line}:{column}.", + path.display() + ); + Exit::Check + } + } +} + +/// Error for [`exec`]. +#[derive(Debug)] +enum ExecError { + /// Failed to read entry in file path. + Entry(walkdir::Error), + /// Failed to parse file path to string. + String, + /// Failed to open file. + File(std::io::Error), + /// Failed to run apply function. + Apply(ApplyError), +} +impl fmt::Display for ExecError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + Self::Entry(entry) => write!(f, "Failed to read entry in file path: {entry}"), + Self::String => write!(f, "Failed to parse file path to string."), + Self::File(file) => write!(f, "Failed to open file: {file}"), + Self::Apply(apply) => write!(f, "Failed to run apply function: {apply}"), + } + } +} + +impl Error for ExecError {} + +/// Wraps functionality from `main` to support returning an error then handling it. +fn exec() -> Result, ExecError> { + let args = CommandLineArgs::parse(); + + let path = args.path.unwrap_or(PathBuf::from(".")); + for entry_res in WalkDir::new(path).follow_links(true) { + let entry = entry_res.map_err(ExecError::Entry)?; + let entry_path = entry.into_path(); + + let path_str = entry_path.to_str().ok_or(ExecError::String)?; + // File paths must not contain any excluded strings. + let no_excluded_strings = !args.exclude.iter().any(|e| path_str.contains(e)); + // The file must not be a `build.rs` file. + let not_build_file = !entry_path.ends_with("build.rs"); + // The file must be a `.rs` file. + let is_rs_file = entry_path.extension().map_or(false, |ext| ext == "rs"); + + if no_excluded_strings && not_build_file && is_rs_file { + let file = OpenOptions::new() + .read(true) + .open(&entry_path) + .map_err(ExecError::File)?; + let res = apply(&args.action, &args.suffix, &args.cfg_attr, file, |_| { + OpenOptions::new() + .write(true) + .truncate(true) + .open(&entry_path) + }) + .map_err(ExecError::Apply)?; + + if let Some(span) = res { + return Ok(Some((entry_path, span.start().line, span.start().column))); + } + } + } + Ok(None) +} + +/// Error for [`apply`]. +#[derive(Debug)] +enum ApplyError { + /// Failed to read file. + Read(std::io::Error), + /// Failed to parse file to utf8. + Utf(core::str::Utf8Error), + /// Failed to parse file to syn ast. + Syn(syn::parse::Error), + /// Failed to get write target. + Target(std::io::Error), + /// Failed to write result to target. + Write(std::io::Error), +} +impl fmt::Display for ApplyError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + Self::Read(read) => write!(f, "Failed to read file: {read}"), + Self::Utf(utf) => write!(f, "Failed to parse file to utf8: {utf}"), + Self::Syn(syn) => write!(f, "Failed to parse file to syn ast: {syn}"), + Self::Target(target) => write!(f, "Failed to get write target: {target}"), + Self::Write(write) => write!(f, "Failed to write result to target: {write}"), + } + } +} + +impl Error for ApplyError {} + +/// Apply the given action to the given source and outputs the result to the target produced by the +/// given closure. +fn apply( + action: &Action, + suffix: &Option, + cfg_attr: &Option, + mut source: R, + target: impl Fn(R) -> Result, +) -> Result, ApplyError> { + let mut buf = Vec::new(); + source.read_to_end(&mut buf).map_err(ApplyError::Read)?; + let text = core::str::from_utf8(&buf).map_err(ApplyError::Utf)?; + + let ast = syn::parse_file(text).map_err(ApplyError::Syn)?; + + match action { + Action::Strip => { + let mut visitor = StripVisitor( + text.split('\n') + .enumerate() + .map(|(i, x)| (i, String::from(x))) + .collect(), + ); + visitor.visit_file(&ast); + let out = String::from(visitor); + target(source) + .map_err(ApplyError::Target)? + .write_all(out.as_bytes()) + .map_err(ApplyError::Write)?; + Ok(None) + } + Action::Check => { + let mut visitor = CheckVisitor(None); + visitor.visit_file(&ast); + Ok(visitor.0) + } + Action::Fix => { + let mut visitor = FixVisitor { + suffix, + cfg_attr, + list: SegmentedList { + first: String::new(), + inner: text + .split('\n') + .map(|x| (String::from(x), String::new())) + .collect(), + }, + }; + visitor.visit_file(&ast); + let out = String::from(visitor); + target(source) + .map_err(ApplyError::Target)? + .write_all(out.as_bytes()) + .map_err(ApplyError::Write)?; + Ok(None) + } + } +} + +/// Finds the `#[instrument]` attribute on a function. +fn find_instrumented(attrs: &[syn::Attribute]) -> Option<&syn::Attribute> { + attrs.iter().find(|a| is_instrumented(a).is_some()) +} + +/// Checks if a `syn::Attribute` is `#[instrument]`. +fn is_instrumented(attr: &syn::Attribute) -> Option<&syn::Attribute> { + match &attr.meta { + syn::Meta::List(syn::MetaList { path, tokens, .. }) => { + // `#[instrument]` + let instrumented = matches!(path.segments.last(), Some(syn::PathSegment { ident, .. }) if ident == "instrument"); + // `#[cfg_attr(.. , instrument)]` + let attr_instrumented = matches!(path.segments.last(), Some(syn::PathSegment { ident, .. }) if ident == "cfg_attr") && tokens.clone().into_iter().any(|token| matches!(token, proc_macro2::TokenTree::Ident(ident) if ident == "instrument")); + + (instrumented || attr_instrumented).then_some(attr) + } + syn::Meta::Path(syn::Path { segments, .. }) => { + let x = matches!(segments.last(), Some(syn::PathSegment { ident, .. }) if ident == "instrument"); + x.then_some(attr) + } + syn::Meta::NameValue(_) => None, + } +} + +/// The description of attributes on a function signature we care about. +struct Desc { + /// Does the function have the `#[tracing::instrument]` attribute macro? + instrumented: bool, + /// Does the function have the `#[test]` attribute macro? + test: bool, +} + +// A function is considered instrumented if it has the `#[instrument]` attribute or the `#[test]` +// attribute. +/// Returns a tuple where the 1st element is whether `tracing::instrument` is found in the list of +/// attributes and the 2nd is whether `clippy_tracing_attributes::skip` is found in the list of +/// attributes. +fn check_attributes(attrs: &[syn::Attribute]) -> Desc { + let mut instrumented = false; + let mut test = false; + + for attr in attrs { + // Match `#[instrument]` and `#[cfg_attr(.., instrument)]`. + if is_instrumented(attr).is_some() { + instrumented = true; + } + + // Match `#[test]` or `#[kani::proof]`. + if match &attr.meta { + syn::Meta::List(syn::MetaList { path, .. }) => { + matches!(path.segments.last(), Some(syn::PathSegment { ident, .. }) if ident == "proof") + } + syn::Meta::Path(syn::Path { segments, .. }) => { + matches!(segments.last(), Some(syn::PathSegment { ident, .. }) if ident == "test" || ident == "proof") + } + syn::Meta::NameValue(_) => false, + } { + test = true; + } + } + Desc { instrumented, test } +} diff --git a/src/clippy-tracing/tests/integration_tests.rs b/src/clippy-tracing/tests/integration_tests.rs new file mode 100644 index 00000000000..2a730fbbcb4 --- /dev/null +++ b/src/clippy-tracing/tests/integration_tests.rs @@ -0,0 +1,489 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +use std::fs::{remove_file, OpenOptions}; +use std::io::{Read, Write}; +use std::process::Command; + +use uuid::Uuid; + +const BINARY: &str = env!("CARGO_BIN_EXE_clippy-tracing"); + +fn setup(text: &str) -> String { + let id = Uuid::new_v4(); + let path = format!("/tmp/{id}.rs"); + let mut file = OpenOptions::new() + .create(true) + .read(false) + .write(true) + .open(&path) + .unwrap(); + file.write_all(text.as_bytes()).unwrap(); + path +} + +fn check_file(text: &str, path: &str) { + let mut file = OpenOptions::new() + .create(false) + .read(true) + .write(false) + .open(path) + .unwrap(); + let mut buffer = String::new(); + file.read_to_string(&mut buffer).unwrap(); + assert_eq!(text, buffer); +} + +fn fix(given: &str, expected: &str, cfg_attr: Option<&'static str>) { + let path = setup(given); + + let output = if let Some(cfg_attr) = cfg_attr { + Command::new(BINARY) + .args(["--action", "fix", "--path", &path, "--cfg-attr", cfg_attr]) + .output() + .unwrap() + } else { + Command::new(BINARY) + .args(["--action", "fix", "--path", &path]) + .output() + .unwrap() + }; + assert_eq!(std::str::from_utf8(&output.stdout).unwrap(), ""); + assert_eq!(std::str::from_utf8(&output.stderr).unwrap(), ""); + assert_eq!(output.status.code(), Some(0)); + check_file(expected, &path); + remove_file(path).unwrap(); +} + +fn strip(given: &str, expected: &str) { + let path = setup(given); + let output = Command::new(BINARY) + .args(["--action", "strip", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + check_file(expected, &path); + remove_file(path).unwrap(); +} + +#[test] +fn exec_error() { + // Create file path for a file that doesn't exist. + let id = Uuid::new_v4(); + let path = format!("/tmp/{id}.rs"); + + let output = Command::new(BINARY) + .args(["--action", "check", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(1)); + assert_eq!(output.stdout, []); + let expected_stderr = format!( + "Error: Failed to read entry in file path: IO error for operation on {path}: No such file \ + or directory (os error 2)\n" + ); + assert_eq!(output.stderr, expected_stderr.as_bytes()); +} + +#[test] +fn fix_one() { + const GIVEN: &str = "fn main() { }\nfn add(lhs: i32, rhs: i32) {\n lhs + rhs\n}"; + const EXPECTED: &str = "#[log_instrument::instrument]\nfn main() { \ + }\n#[log_instrument::instrument]\nfn add(lhs: i32, rhs: i32) {\n \ + lhs + rhs\n}"; + fix(GIVEN, EXPECTED, None); +} + +#[test] +fn fix_two() { + const GIVEN: &str = "impl Unit {\n fn one() {}\n}"; + const EXPECTED: &str = "impl Unit {\n #[log_instrument::instrument]\n fn one() {}\n}"; + fix(GIVEN, EXPECTED, None); +} + +#[test] +fn fix_three() { + const GIVEN: &str = "impl Unit {\n fn one() {}\n}"; + const EXPECTED: &str = "impl Unit {\n #[cfg_attr(feature = \"tracing\", \ + log_instrument::instrument)]\n fn one() {}\n}"; + fix(GIVEN, EXPECTED, Some("feature = \"tracing\"")); +} + +#[test] +fn check_one() { + const GIVEN: &str = "fn main() { }"; + let path = setup(GIVEN); + let output = Command::new(BINARY) + .args(["--action", "check", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(2)); + let expected_stdout = format!("Missing instrumentation at {path}:1:0.\n"); + assert_eq!(output.stdout, expected_stdout.as_bytes()); + assert_eq!(output.stderr, []); + remove_file(path).unwrap(); +} + +#[test] +fn check_two() { + const GIVEN: &str = "#[log_instrument::instrument]\nfn main() { }\n#[test]\nfn my_test() { }"; + let path: String = setup(GIVEN); + let output = Command::new(BINARY) + .args(["--action", "check", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + remove_file(path).unwrap(); +} + +#[test] +fn check_three() { + const GIVEN: &str = "impl Unit {\n #[cfg_attr(feature = \"tracing\", \ + tracing::instrument(level = \"trace\", skip()))]\n fn one() {}\n}"; + let path = setup(GIVEN); + let output = Command::new(BINARY) + .args([ + "--action", + "check", + "--path", + &path, + "--cfg-attr", + "feature = \"tracing\"", + ]) + .output() + .unwrap(); + assert_eq!(std::str::from_utf8(&output.stdout).unwrap(), ""); + assert_eq!(std::str::from_utf8(&output.stderr).unwrap(), ""); + assert_eq!(output.status.code(), Some(0)); + remove_file(path).unwrap(); +} + +#[test] +fn strip_one() { + const GIVEN: &str = "#[log_instrument::instrument]\nfn main() { }"; + const EXPECTED: &str = "fn main() { }"; + strip(GIVEN, EXPECTED); +} + +#[test] +fn strip_two() { + const GIVEN: &str = "#[log_instrument::instrument]\nfn main() { }"; + const EXPECTED: &str = "fn main() { }"; + strip(GIVEN, EXPECTED); +} + +#[test] +fn strip_three() { + const EXPECTED: &str = "impl Unit {\n fn one() {}\n}"; + const GIVEN: &str = "impl Unit {\n #[log_instrument::instrument]\n fn one() {}\n}"; + strip(GIVEN, EXPECTED); +} + +#[test] +fn exclude() { + const GIVEN: &str = "fn main() { }\nfn add(lhs: i32, rhs: i32) {\n lhs + rhs\n}"; + const EXPECTED: &str = "#[log_instrument::instrument]\nfn main() { \ + }\n#[log_instrument::instrument]\nfn add(lhs: i32, rhs: i32) {\n \ + lhs + rhs\n}"; + + let dir_path = format!("/tmp/{}", Uuid::new_v4()); + let _dir = std::fs::create_dir(&dir_path).unwrap(); + + dbg!(&dir_path); + + let file_path_one = format!("{dir_path}/{}.rs", Uuid::new_v4()); + let file_path_two = format!("{dir_path}/{}.rs", Uuid::new_v4()); + + dbg!(&file_path_one); + dbg!(&file_path_two); + + let mut file_one = OpenOptions::new() + .create(true) + .read(false) + .write(true) + .open(&file_path_one) + .unwrap(); + file_one.write_all(GIVEN.as_bytes()).unwrap(); + + let mut file_two = OpenOptions::new() + .create(true) + .read(false) + .write(true) + .open(&file_path_two) + .unwrap(); + file_two.write_all(GIVEN.as_bytes()).unwrap(); + + let output = Command::new(BINARY) + .args([ + "--action", + "fix", + "--path", + &dir_path, + "--exclude", + &file_path_two, + ]) + .output() + .unwrap(); + + assert_eq!(std::str::from_utf8(&output.stdout).unwrap(), ""); + assert_eq!(std::str::from_utf8(&output.stderr).unwrap(), ""); + assert_eq!(output.status.code(), Some(0)); + + check_file(EXPECTED, &file_path_one); + check_file(GIVEN, &file_path_two); + + remove_file(file_path_one).unwrap(); + remove_file(file_path_two).unwrap(); + std::fs::remove_dir(dir_path).unwrap(); +} + +#[test] +fn readme() { + const GIVEN: &str = r#"fn main() { + println!("Hello World!"); +} +fn add(lhs: i32, rhs: i32) -> i32 { + lhs + rhs +} +#[cfg(tests)] +mod tests { + fn sub(lhs: i32, rhs: i32) -> i32 { + lhs - rhs + } + #[test] + fn test_one() { + assert_eq!(add(1,1), sub(2, 1)); + } +}"#; + let path: String = setup(GIVEN); + + // Check + let output = Command::new(BINARY) + .args(["--action", "check", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(2)); + let missing = format!("Missing instrumentation at {path}:9:4.\n"); + assert_eq!(output.stdout, missing.as_bytes()); + assert_eq!(output.stderr, []); + + const EXPECTED: &str = r#"#[log_instrument::instrument] +fn main() { + println!("Hello World!"); +} +#[log_instrument::instrument] +fn add(lhs: i32, rhs: i32) -> i32 { + lhs + rhs +} +#[cfg(tests)] +mod tests { + #[log_instrument::instrument] + fn sub(lhs: i32, rhs: i32) -> i32 { + lhs - rhs + } + #[test] + fn test_one() { + assert_eq!(add(1,1), sub(2, 1)); + } +}"#; + + // Fix + let output = Command::new(BINARY) + .args(["--action", "fix", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + check_file(EXPECTED, &path); + + // Check + let output = Command::new(BINARY) + .args(["--action", "check", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + + // Strip + let output = Command::new(BINARY) + .args(["--action", "strip", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + check_file(GIVEN, &path); +} + +#[test] +fn readme_empty_suffix() { + const GIVEN: &str = r#"fn main() { + println!("Hello World!"); +} +fn add(lhs: i32, rhs: i32) -> i32 { + lhs + rhs +} +#[cfg(tests)] +mod tests { + fn sub(lhs: i32, rhs: i32) -> i32 { + lhs - rhs + } + #[test] + fn test_one() { + assert_eq!(add(1,1), sub(2, 1)); + } +}"#; + let path: String = setup(GIVEN); + + // Check + let output = Command::new(BINARY) + .args(["--action", "check", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(2)); + let missing = format!("Missing instrumentation at {path}:9:4.\n"); + assert_eq!(output.stdout, missing.as_bytes()); + assert_eq!(output.stderr, []); + + const EXPECTED: &str = r#"#[instrument] +fn main() { + println!("Hello World!"); +} +#[instrument] +fn add(lhs: i32, rhs: i32) -> i32 { + lhs + rhs +} +#[cfg(tests)] +mod tests { + #[instrument] + fn sub(lhs: i32, rhs: i32) -> i32 { + lhs - rhs + } + #[test] + fn test_one() { + assert_eq!(add(1,1), sub(2, 1)); + } +}"#; + + // Fix + let output = Command::new(BINARY) + .args(["--action", "fix", "--suffix", "", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + check_file(EXPECTED, &path); + + // Check + let output = Command::new(BINARY) + .args(["--action", "check", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + + // Strip + let output = Command::new(BINARY) + .args(["--action", "strip", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + check_file(GIVEN, &path); +} + +#[test] +fn readme_custom_suffix() { + const GIVEN: &str = r#"fn main() { + println!("Hello World!"); +} +fn add(lhs: i32, rhs: i32) -> i32 { + lhs + rhs +} +#[cfg(tests)] +mod tests { + fn sub(lhs: i32, rhs: i32) -> i32 { + lhs - rhs + } + #[test] + fn test_one() { + assert_eq!(add(1,1), sub(2, 1)); + } +}"#; + let path: String = setup(GIVEN); + + // Check + let output = Command::new(BINARY) + .args(["--action", "check", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(2)); + let missing = format!("Missing instrumentation at {path}:9:4.\n"); + assert_eq!(output.stdout, missing.as_bytes()); + assert_eq!(output.stderr, []); + + const EXPECTED: &str = r#"#[my::custom::suffix::instrument] +fn main() { + println!("Hello World!"); +} +#[my::custom::suffix::instrument] +fn add(lhs: i32, rhs: i32) -> i32 { + lhs + rhs +} +#[cfg(tests)] +mod tests { + #[my::custom::suffix::instrument] + fn sub(lhs: i32, rhs: i32) -> i32 { + lhs - rhs + } + #[test] + fn test_one() { + assert_eq!(add(1,1), sub(2, 1)); + } +}"#; + + // Fix + let output = Command::new(BINARY) + .args([ + "--action", + "fix", + "--suffix", + "my::custom::suffix::", + "--path", + &path, + ]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + check_file(EXPECTED, &path); + + // Check + let output = Command::new(BINARY) + .args(["--action", "check", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + + // Strip + let output = Command::new(BINARY) + .args(["--action", "strip", "--path", &path]) + .output() + .unwrap(); + assert_eq!(output.status.code(), Some(0)); + assert_eq!(output.stdout, []); + assert_eq!(output.stderr, []); + check_file(GIVEN, &path); +} diff --git a/src/cpu-template-helper/Cargo.toml b/src/cpu-template-helper/Cargo.toml index e1a6d04f9ce..19240850ea1 100644 --- a/src/cpu-template-helper/Cargo.toml +++ b/src/cpu-template-helper/Cargo.toml @@ -14,6 +14,7 @@ bench = false clap = { version = "4.4.7", features = ["derive", "string"] } displaydoc = "0.2.4" libc = "0.2.149" +log-instrument = { path = "../log-instrument", optional = true } serde = { version = "1.0.190", features = ["derive"] } serde_json = "1.0.108" thiserror = "1.0.50" @@ -22,3 +23,6 @@ vmm = { path = "../vmm" } [dev-dependencies] utils = { path = "../utils" } + +[features] +tracing = ["log-instrument"] diff --git a/src/firecracker/Cargo.toml b/src/firecracker/Cargo.toml index 1c8630da9a6..4502829acb6 100644 --- a/src/firecracker/Cargo.toml +++ b/src/firecracker/Cargo.toml @@ -16,6 +16,7 @@ bench = false displaydoc = "0.2.4" event-manager = "0.3.0" libc = "0.2.149" +log-instrument = { path = "../log-instrument", optional = true } serde_json = "1.0.108" thiserror = "1.0.50" timerfd = "1.5.0" @@ -40,6 +41,9 @@ seccompiler = { path = "../seccompiler" } serde = { version = "1.0.190" } serde_json = "1.0.108" +[features] +tracing = ["log-instrument", "api_server/tracing", "seccompiler/tracing", "snapshot/tracing", "utils/tracing", "vmm/tracing"] + [[example]] name = "uffd_malicious_handler" path = "examples/uffd/malicious_handler.rs" diff --git a/src/jailer/Cargo.toml b/src/jailer/Cargo.toml index 9f414d980a3..37f598ccb6a 100644 --- a/src/jailer/Cargo.toml +++ b/src/jailer/Cargo.toml @@ -13,8 +13,12 @@ bench = false [dependencies] libc = "0.2.149" +log-instrument = { path = "../log-instrument", optional = true } nix = { version = "0.27.1", default-features = false, features = ["dir"] } regex = { version = "1.10.2", default-features = false, features = ["std"] } thiserror = "1.0.50" utils = { path = "../utils" } + +[features] +tracing = ["log-instrument"] diff --git a/src/log-instrument-macros/Cargo.toml b/src/log-instrument-macros/Cargo.toml new file mode 100644 index 00000000000..bb997c87d1c --- /dev/null +++ b/src/log-instrument-macros/Cargo.toml @@ -0,0 +1,16 @@ +[package] +name = "log-instrument-macros" +version = "0.1.0" +authors = ["Amazon Firecracker team "] +edition = "2021" +description = "Offers an attribute procedural macro that adds `log::trace!` events at the start and end of attributed functions." +license = "Apache-2.0" + +[lib] +proc-macro = true +bench = false + +[dependencies] +proc-macro2 = "1.0.66" +quote = "1.0.33" +syn = { version = "2.0.29", features = ["full", "extra-traits"] } diff --git a/src/log-instrument-macros/src/lib.rs b/src/log-instrument-macros/src/lib.rs new file mode 100644 index 00000000000..8e4b1a21710 --- /dev/null +++ b/src/log-instrument-macros/src/lib.rs @@ -0,0 +1,38 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +#![warn(clippy::pedantic)] + +extern crate proc_macro; +use quote::quote; +use syn::parse_quote; + +/// Adds `log::trace!` events at the start and end of an attributed function. +/// +/// # Panics +/// +/// When applied to anything other than a function. +#[proc_macro_attribute] +pub fn instrument( + _attr: proc_macro::TokenStream, + item: proc_macro::TokenStream, +) -> proc_macro::TokenStream { + let input = syn::parse_macro_input!(item as syn::Item); + + let syn::Item::Fn(mut item_fn) = input else { + panic!("Instrument macro can only be on functions.") + }; + + let clippy_attr: syn::Attribute = parse_quote! { + #[allow(clippy::items_after_statements)] + }; + item_fn.attrs.push(clippy_attr); + + let item_fn_ident = item_fn.sig.ident.to_string(); + let new_stmt: syn::Stmt = + parse_quote! { let __ = log_instrument::__Instrument::new(#item_fn_ident); }; + item_fn.block.stmts.insert(0, new_stmt); + + let out = quote! { #item_fn }; + proc_macro::TokenStream::from(out) +} diff --git a/src/log-instrument/Cargo.toml b/src/log-instrument/Cargo.toml new file mode 100644 index 00000000000..8536d7c383b --- /dev/null +++ b/src/log-instrument/Cargo.toml @@ -0,0 +1,39 @@ +[package] +name = "log-instrument" +version = "0.3.0" +authors = ["Amazon Firecracker team "] +edition = "2021" +description = "Offers an attribute procedural macro that adds `log::trace!` events at the start and end of attributed functions." +license = "Apache-2.0" + +[lib] +bench = false + +[[bin]] +name = "one" +bench = false + +[[bin]] +name = "two" +bench = false + +[[bin]] +name = "three" +bench = false + +[[bin]] +name = "four" +bench = false + +[[bin]] +name = "five" +bench = false + +[[bin]] +name = "six" +bench = false + +[dependencies] +env_logger = "0.10.0" +log = "0.4.20" +log-instrument-macros = { path = "../log-instrument-macros" } diff --git a/src/log-instrument/README.md b/src/log-instrument/README.md new file mode 100644 index 00000000000..457b3ea0c9f --- /dev/null +++ b/src/log-instrument/README.md @@ -0,0 +1,58 @@ +# log-instrument + +Offers an attribute procedural macro that adds +[`log::trace!`](https://docs.rs/log/latest/log/macro.trace.html) events +at the start and end of attributed functions. + +## Example + +```rust +use log::*; + +fn main() { + env_logger::builder() + .filter_level(LevelFilter::Trace) + .init(); + info!("{}", one(2)); + info!("{}", one(3)); + info!("{}", one(4)); +} +#[log_instrument::instrument] +fn one(x: u32) -> u32 { + let cmp = x == 2; + debug!("cmp: {cmp}"); + if cmp { + return 4; + } + two(x + 3) +} +#[log_instrument::instrument] +fn two(x: u32) -> u32 { + let res = x % 2; + debug!("res: {res}"); + res +} +``` + +Outputs: + +``` +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)>>one +[2023-10-12T16:38:00Z DEBUG six] cmp: true +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)<>one +[2023-10-12T16:38:00Z DEBUG six] cmp: false +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)::one>>two +[2023-10-12T16:38:00Z DEBUG six] res: 0 +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)::one<>one +[2023-10-12T16:38:00Z DEBUG six] cmp: false +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)::one>>two +[2023-10-12T16:38:00Z DEBUG six] res: 1 +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)::one<>); + +impl MyStruct { + #[log_instrument::instrument] + fn one(&mut self) -> Option<&mut [String]> { + const SOMETHING: u32 = 23; + match &mut self.0 { + Some(y) => { + debug!("{y:?}"); + debug!("{SOMETHING}"); + Some(y) + } + _ => None, + } + } +} diff --git a/src/log-instrument/src/bin/four.rs b/src/log-instrument/src/bin/four.rs new file mode 100644 index 00000000000..803cb6d8e9f --- /dev/null +++ b/src/log-instrument/src/bin/four.rs @@ -0,0 +1,28 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +use log::*; + +fn main() { + env_logger::builder() + .filter_level(LevelFilter::Trace) + .init(); + let mut my_struct = MyStruct(None); + info!("{:?}", my_struct.one()); + let mut my_struct = MyStruct(Some(vec![String::from("a"), String::from("b")])); + info!("{:?}", my_struct.one()); +} +struct MyStruct(Option>); + +impl MyStruct { + #[log_instrument::instrument] + fn one(&mut self) -> Option<&mut [String]> { + match &mut self.0 { + Some(y) => { + debug!("{y:?}"); + Some(y) + } + _ => None, + } + } +} diff --git a/src/log-instrument/src/bin/one.rs b/src/log-instrument/src/bin/one.rs new file mode 100644 index 00000000000..57836a0330d --- /dev/null +++ b/src/log-instrument/src/bin/one.rs @@ -0,0 +1,22 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +use log::*; + +fn main() { + env_logger::builder() + .filter_level(LevelFilter::Trace) + .init(); + info!("{}", one(2)); + info!("{}", one(3)); + info!("{}", one(4)); +} +#[log_instrument::instrument] +fn one(x: u32) -> u32 { + let cmp = x == 2; + debug!("cmp: {cmp}"); + if cmp { + return 4; + } + x + 3 +} diff --git a/src/log-instrument/src/bin/six.rs b/src/log-instrument/src/bin/six.rs new file mode 100644 index 00000000000..443b36adea3 --- /dev/null +++ b/src/log-instrument/src/bin/six.rs @@ -0,0 +1,28 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +use log::*; + +fn main() { + env_logger::builder() + .filter_level(LevelFilter::Trace) + .init(); + info!("{}", one(2)); + info!("{}", one(3)); + info!("{}", one(4)); +} +#[log_instrument::instrument] +fn one(x: u32) -> u32 { + let cmp = x == 2; + debug!("cmp: {cmp}"); + if cmp { + return 4; + } + two(x + 3) +} +#[log_instrument::instrument] +fn two(x: u32) -> u32 { + let res = x % 2; + debug!("res: {res}"); + res +} diff --git a/src/log-instrument/src/bin/three.rs b/src/log-instrument/src/bin/three.rs new file mode 100644 index 00000000000..13f8e0049ce --- /dev/null +++ b/src/log-instrument/src/bin/three.rs @@ -0,0 +1,25 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +use log::*; + +fn main() { + env_logger::builder() + .filter_level(LevelFilter::Trace) + .init(); + info!("{:?}", one(&mut None)); + info!( + "{:?}", + one(&mut Some(vec![String::from("a"), String::from("b")])) + ); +} +#[log_instrument::instrument] +fn one(x: &mut Option>) -> Option<&mut [String]> { + match x { + Some(y) => { + debug!("{y:?}"); + Some(y) + } + _ => None, + } +} diff --git a/src/log-instrument/src/bin/two.rs b/src/log-instrument/src/bin/two.rs new file mode 100644 index 00000000000..3c13ae9e782 --- /dev/null +++ b/src/log-instrument/src/bin/two.rs @@ -0,0 +1,25 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +use log::*; + +fn main() { + env_logger::builder() + .filter_level(LevelFilter::Trace) + .init(); + info!("{:?}", one(&None)); + info!( + "{:?}", + one(&Some(vec![String::from("a"), String::from("b")])) + ); +} +#[log_instrument::instrument] +fn one(x: &Option>) -> Option<&[String]> { + match x { + Some(y) => { + debug!("{y:?}"); + Some(y) + } + _ => None, + } +} diff --git a/src/log-instrument/src/lib.rs b/src/log-instrument/src/lib.rs new file mode 100644 index 00000000000..3939dc6df76 --- /dev/null +++ b/src/log-instrument/src/lib.rs @@ -0,0 +1,56 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +use std::collections::HashMap; +use std::fmt::Write; +use std::sync::{Mutex, OnceLock}; + +pub use log_instrument_macros::*; + +type InnerPath = Mutex>>; +static PATH: OnceLock = OnceLock::new(); +fn path() -> &'static InnerPath { + PATH.get_or_init(InnerPath::default) +} + +#[allow(missing_debug_implementations)] +pub struct __Instrument; + +impl __Instrument { + pub fn new(s: &'static str) -> __Instrument { + // Get log + let mut guard = path().lock().unwrap(); + let id = std::thread::current().id(); + let prefix = if let Some(spans) = guard.get_mut(&id) { + let out = spans.iter().fold(String::new(), |mut s, x| { + let _ = write!(s, "::{x}"); + s + }); + spans.push(s); + out + } else { + guard.insert(id, vec![s]); + String::new() + }; + + // Write log + log::trace!("{id:?}{prefix}>>{s}"); + + // Return exit struct + __Instrument + } +} +impl std::ops::Drop for __Instrument { + fn drop(&mut self) { + // Get log + let mut guard = path().lock().unwrap(); + let id = std::thread::current().id(); + let spans = guard.get_mut(&id).unwrap(); + let s = spans.pop().unwrap(); + let out = spans.iter().fold(String::new(), |mut s, x| { + let _ = write!(s, "::{x}"); + s + }); + log::trace!("{id:?}{out}<<{s}"); + } +} diff --git a/src/log-instrument/tests/integration_tests.rs b/src/log-instrument/tests/integration_tests.rs new file mode 100644 index 00000000000..d944232c45d --- /dev/null +++ b/src/log-instrument/tests/integration_tests.rs @@ -0,0 +1,148 @@ +// Copyright 2023 Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +const ONE: &str = env!("CARGO_BIN_EXE_one"); +const TWO: &str = env!("CARGO_BIN_EXE_two"); +const THREE: &str = env!("CARGO_BIN_EXE_three"); +const FOUR: &str = env!("CARGO_BIN_EXE_four"); +const FIVE: &str = env!("CARGO_BIN_EXE_five"); +const SIX: &str = env!("CARGO_BIN_EXE_six"); + +const TIMESTAMP_RANGE: std::ops::Range = 1..20; + +/// Match stderr to expected skipping bytes containing the timestamp. +fn check(actual: &[u8], expected: &[u8]) { + assert_eq!(actual.len(), expected.len()); + let mut j = 0; + for i in 0..actual.len() { + if actual[i] == b'\n' { + j = 0; + } + if TIMESTAMP_RANGE.contains(&j) { + continue; + } + assert_eq!(actual[i], expected[i]); + j += 1; + } +} + +#[test] +fn one() { + let output = std::process::Command::new(ONE).output().unwrap(); + assert!(output.status.success()); + assert_eq!(output.stdout, b""); + let expected_stderr = b"\ + [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)>>one\n\ + [2023-10-12T16:29:00Z DEBUG one] cmp: true\n\ + [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:29:00Z DEBUG one] cmp: false\n\ + [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:29:00Z DEBUG one] cmp: false\n\ + [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:29:30Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:29:30Z DEBUG two] [\"a\", \"b\"]\n\ + [2023-10-12T16:29:30Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:30:04Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:30:04Z DEBUG three] [\"a\", \"b\"]\n\ + [2023-10-12T16:30:04Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:30:37Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:30:37Z DEBUG four] [\"a\", \"b\"]\n\ + [2023-10-12T16:30:37Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:31:12Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:31:12Z DEBUG five] [\"a\", \"b\"]\n\ + [2023-10-12T16:31:12Z DEBUG five] 23\n\ + [2023-10-12T16:31:12Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:31:54Z DEBUG six] cmp: true\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:31:54Z DEBUG six] cmp: false\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one>>two\n\ + [2023-10-12T16:31:54Z DEBUG six] res: 0\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one<>one\n\ + [2023-10-12T16:31:54Z DEBUG six] cmp: false\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one>>two\n\ + [2023-10-12T16:31:54Z DEBUG six] res: 1\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one< Date: Wed, 25 Oct 2023 11:24:03 +0100 Subject: [PATCH 4/5] docs: Tracing doc Add `tracing.md` to document how to use the instrumentation to trace the Firecracker process. Signed-off-by: Jonathan Woollett-Light --- docs/tracing.md | 264 ++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 264 insertions(+) create mode 100644 docs/tracing.md diff --git a/docs/tracing.md b/docs/tracing.md new file mode 100644 index 00000000000..490a85fe130 --- /dev/null +++ b/docs/tracing.md @@ -0,0 +1,264 @@ +# Tracing + +## Introduction + +Firecracker implements a framework for instrumentation based tracing. + +Instrumentation based tracing as defined by +[Sheng Liang on usenix.org](https://www.usenix.org/legacy/publications/library/proceedings/coots99/full_papers/liang/liang_html/node9.html): + +> There are two ways to obtain profiling information: either statistical +> sampling or code instrumentation. Statistical sampling is less +> disruptive to program execution, but cannot provide completely +> accurate information. Code instrumentation, on the other hand, may be +> more disruptive, but allows the profiler to record all the events it +> is interested in. Specifically in CPU time profiling, statistical +> sampling may reveal, for example, the relative percentage of time +> spent in frequently-called methods, whereas code instrumentation can +> report the exact number of time each method is invoked. + +The focus with tracing in Firecracker is to improve debug-ability. + +Enabling tracing adds logs output on each functions entry and exit. +This assists debugging problems that relate to deadlocks or high +latencies by quickly identifying elongated function calls. + +## Implementation + +Firecracker implements instrumentation based tracing via +[`log`](https://github.com/rust-lang/log) and +[`log_instrument`](https://github.com/JonathanWoollett-Light/log-instrument), +outputting a `Trace` level log when entering and exiting every function. + +It is disabled by default at compile-time. Tracing functionality has no +impact on the release binary. + +To enable tracing in Firecracker, add instrumentation with: + +``` +clippy-tracing \ +--action fix \ +--path ./src \ +--exclude vmm_config/logger.rs,virtio/gen,bindings.rs,net/gen,benches,logger/,signal_handler.rs,time.rs +``` + +and re-compile with `--features tracing`: + +``` +cargo build --features tracing +``` + +This will result in an increase in the binary size (~100kb) and a +significant regression in performance (>10x). To mitigate the +performance impact you can filter the tracing output as described in the +next section. + +## Filtering + +You can filter tracing output both at run-time and compile-time. +This can be used to mitigate the performance impact of logging many +traces. + +Run-time filtering is implemented with the `/logger` API call, this can +significantly mitigate the impact on execution time but cannot mitigate +the impact on memory usage. Execution time impact is mitigated by +avoiding constructing and writing the trace log, it still needs to check +the condition in every place it would output a log. Memory usage impact +is not mitigated as the instrumentation remains in the binary unchanged. + +Compile-time filtering is a manual process using the +[`clippy-tracing`](https://github.com/JonathanWoollett-Light/clippy-tracing) +tool. This can almost entirely mitigate the impact on execution time and +the impact on memory usage. + +### Run-time + +You can filter by module path and/or file path at runtime, e.g.: + +```bash +curl -X PUT --unix-socket "${API_SOCKET}" \ + --data "{ + \"level\": \"Trace\", + \"module\": \"api_server::request\", + }" \ + "http://localhost/logger" +``` + +Instrumentation logs are `Trace` level logs, at runtime the level must +be set to `Trace` to see them. The module filter applied here ensures +only logs from the `request` modules within the `api_server` crate will +be output. + +This will mitigate most of the performance regression. + +### Compile-time + +Specific environments can restrict run-time configuration. In these +environments it becomes necessary to support targeted tracing without +run-time re-configuration, for this compile-time filtering must be used. + +To reproduce the same filtering as run-time at compile-time, you can use +[`clippy-tracing`](../src/clippy-tracing) +at compile-time like: + +```bash +# Remove all instrumentation. +clippy-tracing --action strip --path ./src +# Adds instrumentation to the specific file/s. +clippy-tracing --action fix --path ./src/api_server/src/request +# Build Firecracker. +cargo build --features tracing +``` + +Then at run-time: + +```bash +curl -X PUT --unix-socket "${API_SOCKET}" \ + --data "{ + \"level\": \"Trace\", + }" \ + "http://localhost/logger" +``` + +The instrumentation has been stripped from all files other than those at +`./src/api_server/src/request` so we do not need to apply a run-time +filter. Runtime filtering could be applied but in this case it yields no +additional benefit. + +## Example + +In this example we start Firecracker with tracing then make a simple API +call. + +### API call + +``` +~/Projects/firecracker$ sudo curl -X GET --unix-socket "/run/firecracker.socket" "http://localhost/" +{"id":"anonymous-instance","state":"Not started","vmm_version":"1.6.0-dev","app_name":"Firecracker"} +``` + +### Firecracker + +``` +~/Projects/firecracker$ sudo ./firecracker/build/cargo_target/release/firecracker --level Trace +2023-10-13T14:15:38.851263983 [anonymous-instance:main] Running Firecracker v1.6.0-dev +2023-10-13T14:15:38.851316122 [anonymous-instance:main] ThreadId(1)::main::main_exec>>single_value +2023-10-13T14:15:38.851322264 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851325119 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>flag_present +2023-10-13T14:15:38.851335809 [anonymous-instance:main] ThreadId(1)::main::main_exec::flag_present>>value_of +2023-10-13T14:15:38.851338254 [anonymous-instance:main] ThreadId(1)::main::main_exec::flag_present<>single_value +2023-10-13T14:15:38.851349245 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851352721 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>from_args +2023-10-13T14:15:38.851362931 [anonymous-instance:main] ThreadId(1)::main::main_exec<>get_filters +2023-10-13T14:15:38.851368401 [anonymous-instance:main] ThreadId(1)::main::main_exec::get_filters>>get_default_filters +2023-10-13T14:15:38.851372068 [anonymous-instance:main] ThreadId(1)::main::main_exec::get_filters::get_default_filters>>deserialize_binary +2023-10-13T14:15:38.851380033 [anonymous-instance:main] ThreadId(1)::main::main_exec::get_filters::get_default_filters<>filter_thread_categories +2023-10-13T14:15:38.851388098 [anonymous-instance:main] ThreadId(1)::main::main_exec::get_filters::get_default_filters<>single_value +2023-10-13T14:15:38.851400462 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851403507 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>single_value +2023-10-13T14:15:38.851417955 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851420650 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>flag_present +2023-10-13T14:15:38.851430949 [anonymous-instance:main] ThreadId(1)::main::main_exec::flag_present>>value_of +2023-10-13T14:15:38.851434766 [anonymous-instance:main] ThreadId(1)::main::main_exec::flag_present<>flag_present +2023-10-13T14:15:38.851444575 [anonymous-instance:main] ThreadId(1)::main::main_exec::flag_present>>value_of +2023-10-13T14:15:38.851447941 [anonymous-instance:main] ThreadId(1)::main::main_exec::flag_present<>arguments +2023-10-13T14:15:38.851456488 [anonymous-instance:main] ThreadId(1)::main::main_exec<>single_value +2023-10-13T14:15:38.851462679 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851466587 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>as_single_value +2023-10-13T14:15:38.851473239 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>arguments +2023-10-13T14:15:38.851485062 [anonymous-instance:main] ThreadId(1)::main::main_exec<>single_value +2023-10-13T14:15:38.851491925 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851494900 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>single_value +2023-10-13T14:15:38.851502374 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851504629 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>as_single_value +2023-10-13T14:15:38.851508897 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>single_value +2023-10-13T14:15:38.851515559 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851517503 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>single_value +2023-10-13T14:15:38.851525628 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851529045 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>single_value +2023-10-13T14:15:38.851538883 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value>>value_of +2023-10-13T14:15:38.851542330 [anonymous-instance:main] ThreadId(1)::main::main_exec::single_value<>run_with_api +2023-10-13T14:15:38.851664621 [anonymous-instance:main] ThreadId(1)::main::main_exec::run_with_api>>new +2023-10-13T14:15:38.851672586 [anonymous-instance:main] ThreadId(1)::main::main_exec::run_with_api<>init +2023-10-13T14:15:38.851684739 [anonymous-instance:main] ThreadId(1)::main::main_exec::run_with_api<>build_microvm_from_requests +2023-10-13T14:15:38.851728171 [anonymous-instance:main] ThreadId(1)::main::main_exec::run_with_api::build_microvm_from_requests>>default +2023-10-13T14:15:38.851731888 [anonymous-instance:main] ThreadId(1)::main::main_exec::run_with_api::build_microvm_from_requests<>new +2023-10-13T14:15:38.851737830 [anonymous-instance:main] ThreadId(1)::main::main_exec::run_with_api::build_microvm_from_requests<>new +2023-10-13T14:15:38.851761404 [anonymous-instance:fc_api] ThreadId(2)<>run +2023-10-13T14:15:38.851775200 [anonymous-instance:fc_api] ThreadId(2)::run>>apply_filter +2023-10-13T14:15:38.851823462 [anonymous-instance:fc_api] ThreadId(2)::run<>handle_request +2023-10-13T14:15:55.422417909 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request>>try_from +2023-10-13T14:15:55.422420554 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::try_from>>describe +2023-10-13T14:15:55.422424551 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::try_from<>log_received_api_request +2023-10-13T14:15:55.422429270 [anonymous-instance:fc_api] The API server received a Get request on "/". +2023-10-13T14:15:55.422431354 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::try_from<>parse_get_instance_info +2023-10-13T14:15:55.422435211 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::try_from::parse_get_instance_info>>new_sync +2023-10-13T14:15:55.422437165 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::try_from::parse_get_instance_info::new_sync>>new +2023-10-13T14:15:55.422439289 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::try_from::parse_get_instance_info::new_sync<>into_parts +2023-10-13T14:15:55.422450921 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request<>serve_vmm_action_request +2023-10-13T14:15:55.422472552 [anonymous-instance:main] ThreadId(1)::main::main_exec::run_with_api::build_microvm_from_requests>>handle_preboot_request +2023-10-13T14:15:55.422480477 [anonymous-instance:main] ThreadId(1)::main::main_exec::run_with_api::build_microvm_from_requests<>convert_to_response +2023-10-13T14:15:55.422492289 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::serve_vmm_action_request::convert_to_response>>success_response_with_data +2023-10-13T14:15:55.422493983 [anonymous-instance:fc_api] The request was executed successfully. Status code: 200 OK. +2023-10-13T14:15:55.422498331 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::serve_vmm_action_request::convert_to_response::success_response_with_data>>serialize +2023-10-13T14:15:55.422501387 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::serve_vmm_action_request::convert_to_response::success_response_with_data::serialize>>fmt +2023-10-13T14:15:55.422506086 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request::serve_vmm_action_request::convert_to_response::success_response_with_data::serialize<>take_deprecation_message +2023-10-13T14:15:55.422520533 [anonymous-instance:fc_api] ThreadId(2)::run::handle_request< Date: Thu, 26 Oct 2023 15:35:32 +0100 Subject: [PATCH 5/5] docs: `CHANGELOG.md` tracing entry Added an entry in the change log on adding tracing. Signed-off-by: Jonathan Woollett-Light --- CHANGELOG.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 14e90aedf08..aed3b6f70ef 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,9 @@ `snapshot-editor` tool to print MicrovmState of vmstate snapshot file in a readable format. Also made the `vcpu-states` subcommand available on x86_64. +- [#4063](https://github.com/firecracker-microvm/firecracker/pull/4063): + Adds source-level instrumentation based tracing. See + [tracing](./docs/tracing.md) for more details. ### Changed