Add a minimal tracing-subscriber configuration (Azure#104)

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 Azure#83.

[0] https://docs.rs/tracing-subscriber/0.3.18/tracing_subscriber/filter/struct.EnvFilter.html#directives

Author: jeremycline

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"

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<Vec<String>, Error> {
     let mut list_devices: Vec<String> = Vec::new();
 
@@ -90,9 +92,12 @@ pub fn get_mount_device() -> Result<Vec<String>, 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<State = Unmounted> {
     device_path: PathBuf,
     mount_path: PathBuf,
@@ -108,6 +113,7 @@ impl Media<Unmounted> {
         }
     }
 
+    #[instrument]
     pub fn mount(self) -> Result<Media<Mounted>, Error> {
         create_dir_all(&self.mount_path)?;
 
@@ -140,6 +146,7 @@ impl Media<Unmounted> {
 }
 
 impl Media<Mounted> {
+    #[instrument]
     pub fn unmount(self) -> Result<(), Error> {
         let umount_status =
             Command::new("umount").arg(self.mount_path).status()?;
@@ -162,6 +169,7 @@ impl Media<Mounted> {
         }
     }
 
+    #[instrument]
     pub fn read_ovf_env_to_string(&self) -> Result<String, Error> {
         let mut file_path = self.mount_path.clone();
         file_path.push("ovf-env.xml");
@@ -174,6 +182,7 @@ impl Media<Mounted> {
     }
 }
 
+#[instrument(skip_all)]
 pub fn parse_ovf_env(ovf_body: &str) -> Result<Environment, Error> {
     let environment: Environment = from_str(ovf_body)?;
 
@@ -190,6 +199,7 @@ pub fn parse_ovf_env(ovf_body: &str) -> Result<Environment, Error> {
 }
 
 // Mount the given device, get OVF environment data, return it.
+#[instrument(skip_all)]
 pub fn mount_parse_ovf_env(dev: String) -> Result<Environment, Error> {
     let mount_media =
         Media::new(PathBuf::from(dev), PathBuf::from(PATH_MOUNT_POINT));

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<Environment, anyhow::Error> {
     let ovf_devices = media::get_mount_device()?;
     let mut environment: Option<Environment> = None;
@@ -33,6 +38,7 @@ fn get_environment() -> Result<Environment, anyhow::Error> {
         .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(