From de49662b90a80ef9ee1b5207e495aa7437228e70 Mon Sep 17 00:00:00 2001 From: Jeremy Cline Date: Mon, 15 Jul 2024 16:38:02 -0400 Subject: [PATCH] Add a minimal tracing-subscriber configuration MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit While debugging why running azure-init in a local VM hung forever, I added some minimal log configuration to figure out what was happening. Note that this only logs to stderr and is only configurable via the `AZURE_INIT_LOG` environment variable. The most minimal usage is like this: AZURE_INIT_LOG=info azure-init Which emits anything at info level or high. Refer to the tracing-subscriber documentation[0] for more complex examples. Logs look like this: ``` 2024-07-16T14:41:16.924909Z INFO provision: azure_init: new 2024-07-16T14:41:16.928668Z INFO provision:get_environment: azure_init: new ... 2024-07-16T14:41:17.065528Z INFO provision:get_environment: azure_init: close time.busy=133ms time.idle=4.21ms 2024-07-16T14:41:17.073142Z INFO provision:get_username: azure_init: new 2024-07-16T14:41:17.076323Z INFO provision:get_username: azure_init: close time.busy=23.3µs time.idle=3.16ms 2024-07-16T14:41:17.081070Z INFO provision: azure_init: close time.busy=153ms time.idle=3.12ms ``` It's configured to emit logs when a span opens and closes in addition to any explicit `tracing::{debug,info,warn,error}!` call, although we can disable that if folks don't like it. I also added spans to most of the library functions. All the spans are at the default `INFO` level and the default log configuration is to write logs for warning or higher, so running this without specifying `AZURE_INIT_LOG` results in the same behavior as before. This doesn't try to integrate with OpenTelemetry or pipe logs to KVP; those are being wired up in #83. [0] https://docs.rs/tracing-subscriber/0.3.18/tracing_subscriber/filter/struct.EnvFilter.html#directives --- Cargo.toml | 2 ++ libazureinit/src/media.rs | 10 ++++++++++ src/main.rs | 18 ++++++++++++++++++ 3 files changed, 30 insertions(+) diff --git a/Cargo.toml b/Cargo.toml index 7689cd32..d1f6e398 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -12,6 +12,8 @@ description = "A reference implementation for provisioning Linux VMs on Azure." exitcode = "1.1.2" anyhow = "1.0.81" tokio = { version = "1", features = ["full"] } +tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } +tracing = "0.1.40" [dependencies.libazureinit] path = "libazureinit" diff --git a/libazureinit/src/media.rs b/libazureinit/src/media.rs index 77fd586d..3309abd7 100644 --- a/libazureinit/src/media.rs +++ b/libazureinit/src/media.rs @@ -13,6 +13,7 @@ use serde::Deserialize; use serde_xml_rs::from_str; use tracing; +use tracing::instrument; use crate::error::Error; @@ -76,6 +77,7 @@ pub const PATH_MOUNT_POINT: &str = "/run/azure-init/media/"; const CDROM_VALID_FS: &[&str] = &["iso9660", "udf"]; // Get a mounted device with any filesystem for CDROM +#[instrument] pub fn get_mount_device() -> Result, Error> { let mut list_devices: Vec = Vec::new(); @@ -90,9 +92,12 @@ pub fn get_mount_device() -> Result, Error> { } // Some zero-sized structs that just provide states for our state machine +#[derive(Debug)] pub struct Mounted; +#[derive(Debug)] pub struct Unmounted; +#[derive(Debug)] pub struct Media { device_path: PathBuf, mount_path: PathBuf, @@ -108,6 +113,7 @@ impl Media { } } + #[instrument] pub fn mount(self) -> Result, Error> { create_dir_all(&self.mount_path)?; @@ -140,6 +146,7 @@ impl Media { } impl Media { + #[instrument] pub fn unmount(self) -> Result<(), Error> { let umount_status = Command::new("umount").arg(self.mount_path).status()?; @@ -162,6 +169,7 @@ impl Media { } } + #[instrument] pub fn read_ovf_env_to_string(&self) -> Result { let mut file_path = self.mount_path.clone(); file_path.push("ovf-env.xml"); @@ -174,6 +182,7 @@ impl Media { } } +#[instrument(skip_all)] pub fn parse_ovf_env(ovf_body: &str) -> Result { let environment: Environment = from_str(ovf_body)?; @@ -190,6 +199,7 @@ pub fn parse_ovf_env(ovf_body: &str) -> Result { } // Mount the given device, get OVF environment data, return it. +#[instrument(skip_all)] pub fn mount_parse_ovf_env(dev: String) -> Result { let mount_media = Media::new(PathBuf::from(dev), PathBuf::from(PATH_MOUNT_POINT)); diff --git a/src/main.rs b/src/main.rs index a7afffbd..fbc7493c 100644 --- a/src/main.rs +++ b/src/main.rs @@ -14,9 +14,14 @@ use libazureinit::{ reqwest::{header, Client}, HostnameProvisioner, PasswordProvisioner, Provision, UserProvisioner, }; +use tracing::instrument; +use tracing_subscriber::fmt::format::FmtSpan; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::EnvFilter; const VERSION: &str = env!("CARGO_PKG_VERSION"); +#[instrument] fn get_environment() -> Result { let ovf_devices = media::get_mount_device()?; let mut environment: Option = None; @@ -33,6 +38,7 @@ fn get_environment() -> Result { .ok_or_else(|| anyhow::anyhow!("Unable to get list of block devices")) } +#[instrument(skip_all)] fn get_username( instance_metadata: Option<&InstanceMetadata>, environment: Option<&Environment>, @@ -60,6 +66,17 @@ fn get_username( #[tokio::main] async fn main() -> ExitCode { + let stderr = tracing_subscriber::fmt::layer() + .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) + .with_writer(std::io::stderr); + let registry = tracing_subscriber::registry() + .with(stderr) + .with(EnvFilter::from_env("AZURE_INIT_LOG")); + tracing::subscriber::set_global_default(registry).expect( + "Only an application should set the global default; \ + a library is mis-using the tracing API.", + ); + match provision().await { Ok(_) => ExitCode::SUCCESS, Err(e) => { @@ -78,6 +95,7 @@ async fn main() -> ExitCode { } } +#[instrument] async fn provision() -> Result<(), anyhow::Error> { let mut default_headers = header::HeaderMap::new(); let user_agent = header::HeaderValue::from_str(