refactor: make tracing logs consistently structured and searchable

STYLE_GUIDE.md

@@ -162,26 +162,47 @@ count, like per-machine or per-instance attributes.
 All services should emit logs in "logfmt" syntax. This structured logging format allows administrators to efficiently
 search logs by certain attributes (key/value pairs).
 
-When writing log messages, prefer placing common fields as attributes passed to tracing function, instead of using
-string interpolation. For example:
+Tracing events must use a stable, human-readable string literal for the message and record dynamic operational values
+as structured fields whenever a meaningful field name can be derived. Do not interpolate such values into the message,
+including when the event already contains other structured fields.
+
+Describe the event in the message; do not narrate fields that already describe themselves. For example, prefer
+`info!(%domain_id, "Domain created")` over `info!(%domain_id, "Domain created with ID")`, and prefer
+`info!(%instance_id, %ip_address, "Instance is terminating")` over a message ending in `"at address"`. Keep wording
+that conveys a relationship, source, destination, or behavior that the field names alone do not express.
+
+Use native field shorthand for types that implement `tracing::Value`, `%field` for `Display`, and `?field` for `Debug`.
+Use consistent semantic field names rather than incidental local variable names; for example, record an error held in
+`e` as `error = %e`. Do not reuse formatter metadata keys such as `level`; choose a domain-specific key such as
+`configured_log_level` instead.
+
+For example:
 
 ```rust
-fn avoid(machine_id: MachineId) {
+fn avoid(machine_id: MachineId, attempt_number: u32) {
     if let Err(e) = process_machine(machine_id) {
-        tracing::error!("process_machine failed for {machine_id}: {e}");
+        tracing::error!(
+            "failed to process machine {machine_id} on attempt {attempt_number}: {e}"
+        );
     }
 }
-fn prefer(machine_id: MachineId) {
+fn prefer(machine_id: MachineId, attempt_number: u32) {
     if let Err(e) = process_machine(machine_id) {
-        tracing::error!(%machine_id, error=%e, "process_machine failed");
+        tracing::error!(
+            %machine_id,
+            attempt_number,
+            error = %e,
+            "failed to process machine",
+        );
     }
 }
-
 ```
 
-This helps in log parsing, especially when we want to find logs corresponding to a given machine_id. `error` and
-`machine_id` are probably the two most important examples, but try to express other relevant data as fields instead of
-using interpolation if it makes sense.
+Keep intentional presentation formatting intact when the rendered text is itself the payload, such as CLI output,
+aligned tables, or multi-line displays. Passthrough helpers and macros whose purpose is to forward caller-supplied text
+unchanged are also exempt from the literal-message requirement. Preserve special or custom formatting when converting
+it would change behavior; add structured fields alongside it when that can be done without changing the rendered
+output.
 
 ## Core API handlers
 

crates/admin-cli/src/machine/show/cmd.rs

@@ -432,7 +432,10 @@ pub async fn get_next_free_machine(
     flat_vpc_id: Option<VpcId>,
 ) -> Option<Machine> {
     while let Some(id) = machine_ids.pop_front() {
-        tracing::debug!("Checking {}", id);
+        tracing::debug!(
+            machine_id = %id,
+            "Checking machine",
+        );
         if let Ok(machine) = api_client.get_machine(id).await {
             if machine.state != "Ready" {
                 tracing::debug!("Machine is not ready");

crates/admin-cli/src/rpc.rs

@@ -194,8 +194,9 @@ impl ApiClient {
             Ok(ot) => ot,
             Err(e) => {
                 tracing::error!(
-                    "Invalid UuidType from carbide api: {}",
-                    uuid_details.object_type
+                    object_type = uuid_details.object_type,
+                    error = %e,
+                    "Invalid UUID type from Carbide API",
                 );
                 return Err(CarbideCliError::GenericError(e.to_string()));
             }
@@ -226,8 +227,9 @@ impl ApiClient {
             Ok(ot) => ot,
             Err(e) => {
                 tracing::error!(
-                    "Invalid MachineOwner from carbide api: {}",
-                    mac_details.object_type
+                    object_type = mac_details.object_type,
+                    error = %e,
+                    "Invalid machine owner from Carbide API",
                 );
                 return Err(CarbideCliError::GenericError(e.to_string()));
             }
@@ -1585,7 +1587,7 @@ impl ApiClient {
             } else {
                 vf_network_segment_ids.len() / pf_network_segment_ids.len()
             };
-            tracing::debug!("VFs per PF: {vfs_per_pf}");
+            tracing::debug!(vfs_per_pf, "VFs per PF",);
 
             let mut next_device_instance = HashMap::new();
 
@@ -1684,7 +1686,7 @@ impl ApiClient {
                 // pf_vpc_prefix_ids is checked for empty above (len() cannot be 0)
                 vf_vpc_prefix_ids.len() / pf_vpc_prefix_ids.len()
             };
-            tracing::debug!("VFs per PF: {vfs_per_pf}");
+            tracing::debug!(vfs_per_pf, "VFs per PF",);
             let mut vf_chunk_iter = vf_vpc_prefix_ids.chunks(vfs_per_pf);
             let mut ipv6_vf_chunk_iter = allocate_instance.ipv6_vf_prefix_id.chunks(vfs_per_pf);
             for (map_index, i) in discovery_info
@@ -1729,7 +1731,10 @@ impl ApiClient {
                             }),
                         routing_profile: None,
                     };
-                    tracing::debug!("Adding interface: {:?}", new_interface);
+                    tracing::debug!(
+                        new_interface = ?new_interface,
+                        "Adding interface",
+                    );
 
                     interface_configs.push(new_interface);
 
@@ -1761,12 +1766,18 @@ impl ApiClient {
                                 routing_profile: None,
                             };
                             vf_function_id += 1;
-                            tracing::debug!("Adding interface: {:?}", new_interface);
+                            tracing::debug!(
+                                new_interface = ?new_interface,
+                                "Adding interface",
+                            );
                             interface_configs.push(new_interface);
                         }
                     }
                 } else {
-                    tracing::debug!("No pci device info for interface: {i:?}");
+                    tracing::debug!(
+                        interface = ?i,
+                        "No PCI device info",
+                    );
                 }
             }
 

crates/agent/src/agent_platform.rs

@@ -65,16 +65,16 @@ impl ManagedFile {
         if !destination_exists {
             safe_copy(self.path.as_path(), source_path).inspect(|_| {
                 tracing::info!(
-                    "Copied file contents from {src} to {dst}",
-                    src = source_path.display(),
-                    dst = self.path.display()
+                    source_path = %source_path.display(),
+                    destination_path = %self.path.display(),
+                    "Copied file contents"
                 );
             })
         } else {
             tracing::debug!(
-                "File {dst} already exists, will not be updated from {src}",
-                src = source_path.display(),
-                dst = self.path.display()
+                source_path = %source_path.display(),
+                destination_path = %self.path.display(),
+                "File already exists, will not be updated"
             );
             Ok(())
         }

crates/agent/src/astra_weave.rs

@@ -292,10 +292,7 @@ async fn create_weave_ew_vpc_virtual_networks(
             continue;
         }
 
-        tracing::info!(
-            "Created virtual network from astra attachment status {:?}",
-            astra_attachment_status
-        );
+        tracing::info!(?astra_attachment_status, "Created virtual network");
     }
 
     Ok(())
@@ -340,8 +337,8 @@ async fn delete_stale_weave_ew_vpc_virtual_networks(
         match weave_ew_vpc_delete_virtual_network(socket_path, delete_vni_req).await {
             Ok(_) => {
                 tracing::info!(
-                    "Deleted stale virtual network {:?} from DOCA Weave server",
-                    virtual_network
+                    ?virtual_network,
+                    "Deleted stale virtual network from DOCA Weave server"
                 );
             }
             Err(err) => {
@@ -566,8 +563,8 @@ async fn create_or_recreate_weave_ew_vpc_astra_attachment(
     }
 
     tracing::info!(
-        "Created virtual network attachment for attachment status {:?}",
-        astra_attachment_status
+        ?astra_attachment_status,
+        "Created virtual network attachment"
     );
 
     Ok(())
@@ -625,8 +622,8 @@ async fn delete_stale_weave_ew_vpc_astra_attachments(
             Ok(_) => {
                 deleted_attachment_ids.insert(del_attachment_id);
                 tracing::info!(
-                    "Deleted stale virtual network attachment {:?} from DOCA Weave server",
-                    virtual_network_attachment
+                    ?virtual_network_attachment,
+                    "Deleted stale virtual network attachment from DOCA Weave server"
                 );
             }
             Err(err) => {
@@ -699,8 +696,8 @@ pub async fn delete_match_attachment_with_vni_changed(
         Ok(_) => {
             deleted_attachment_ids.insert(delete_attachment_id);
             tracing::info!(
-                "Deleted mismatched virtual network attachment {:?} from DOCA Weave server",
-                match_attachment.as_ref().unwrap()
+                ?match_attachment,
+                "Deleted mismatched virtual network attachment from DOCA Weave server"
             );
         }
         Err(err) => {
@@ -835,7 +832,8 @@ async fn build_synced_astra_config_status_if_version_unchanged(
     // the astra config despite the matching revision, fall back to a full
     // reconcile (return None) rather than erroring, so the drift is repaired.
     tracing::trace!(
-        "AstraConfig version {nico_spx_version} has no changes, copying attachment status"
+        spx_version = %nico_spx_version,
+        "AstraConfig version has no changes, copying attachment status"
     );
     match sync_astra_config_status_from_weave_ew_vpc_attachments(
         astra_config,
@@ -845,7 +843,8 @@ async fn build_synced_astra_config_status_if_version_unchanged(
         Err(err) => {
             tracing::warn!(
                 error = format!("{err:#}"),
-                "AstraConfig version {nico_spx_version} matches, but DOCA Weave state drifted; running full reconcile"
+                spx_version = %nico_spx_version,
+                "AstraConfig version matches, but DOCA Weave state drifted; running full reconcile"
             );
             Ok(None)
         }

crates/agent/src/containerd/container.rs

@@ -18,7 +18,7 @@ use std::collections::HashMap;
 use std::path::PathBuf;
 
 use serde::{Deserialize, Serialize};
-use tracing::log::error;
+use tracing::error;
 
 use crate::containerd::image::{Image, ImageNameComponent};
 use crate::containerd::{BashCommand, Command};
@@ -226,7 +226,7 @@ async fn get_container_images() -> eyre::Result<String> {
         let test_data_dir = PathBuf::from(TEST_DATA_DIR);
 
         std::fs::read_to_string(test_data_dir.join("container_images.json")).map_err(|e| {
-            error!("Could not read container_images.json: {e}");
+            error!(error = %e, "Could not read container_images.json");
             eyre::eyre!("Could not read container_images.json: {}", e)
         })
     } else {
@@ -235,7 +235,7 @@ async fn get_container_images() -> eyre::Result<String> {
             .run()
             .await
             .map_err(|e| {
-                error!("Could not read container_images.json: {e}");
+                error!(error = %e, "Could not read container_images.json");
                 eyre::eyre!("Could not read container_images.json: {}", e)
             })?;
         Ok(result)
@@ -250,7 +250,7 @@ async fn get_containers() -> eyre::Result<String> {
         println!("Path: {}", test_data_dir.join("containers.json").display());
 
         std::fs::read_to_string(test_data_dir.join("containers.json")).map_err(|e| {
-            error!("Could not read containers.json: {e}");
+            error!(error = %e, "Could not read containers.json");
             eyre::eyre!("Could not read containers.json: {}", e)
         })
     } else {
@@ -259,7 +259,7 @@ async fn get_containers() -> eyre::Result<String> {
             .run()
             .await
             .map_err(|e| {
-                error!("Could not read containers.json: {e}");
+                error!(error = %e, "Could not read containers.json");
                 eyre::eyre!("Could not read containers.json: {}", e)
             })?;
         Ok(result)
@@ -274,7 +274,7 @@ async fn get_pod_containers(pod_id: &str) -> eyre::Result<String> {
         println!("Path: {}", test_data_dir.join("containers.json").display());
 
         std::fs::read_to_string(test_data_dir.join("containers.json")).map_err(|e| {
-            error!("Could not read containers.json: {e}");
+            error!(error = %e, "Could not read containers.json");
             eyre::eyre!("Could not read containers.json: {}", e)
         })
     } else {
@@ -284,7 +284,7 @@ async fn get_pod_containers(pod_id: &str) -> eyre::Result<String> {
             .run()
             .await
             .map_err(|e| {
-                error!("Could not read containers.json: {e}");
+                error!(error = %e, "Could not read containers.json");
                 eyre::eyre!("Could not read containers.json: {}", e)
             })?;
         Ok(result)
@@ -343,9 +343,9 @@ mod tests {
     #[tokio::test]
     async fn test_find_container_by_name() {
         let containers = Containers::list().await.expect("Could not get containers");
-        tracing::info!("Container: {:?}", containers);
+        tracing::info!(?containers, "Listed containers");
         let container = containers.find_by_name("doca-hbn").unwrap();
-        tracing::info!("Container: {:?}", container);
+        tracing::info!(?container, "Found container by name");
         assert_eq!(container.metadata.name, "doca-hbn");
         assert_eq!(container.state, ContainerState::Running);
     }

crates/agent/src/containerd/image.rs

@@ -19,7 +19,7 @@ use std::fmt::{Display, Formatter};
 
 use regex::Regex;
 use serde::{Deserialize, Serialize};
-use tracing::log::trace;
+use tracing::trace;
 
 /// Represents the individual components of a container image name.
 /// e.g.
@@ -76,7 +76,7 @@ where
     let vec: Vec<String> = Vec::deserialize(deserializer)?;
     let initial: Vec<ImageNameComponent> = Vec::new();
 
-    trace!("Container name component: {vec:?}");
+    trace!(image_name_components = ?vec, "Container name component");
     vec.iter().try_fold(initial, |mut accum, value| {
         let re = Regex::new(r#"(.+)\/(.+):(.+)"#).unwrap();
         re.captures(value.as_str())

crates/agent/src/dhcp_server_grpc_client.rs

@@ -132,7 +132,9 @@ pub async fn get_dhcp_timestamps(
             let id = e
                 .host_interface_id
                 .parse::<MachineInterfaceId>()
-                .map_err(|err| tracing::warn!("Skipping unparseable host_interface_id: {err}"))
+                .map_err(
+                    |err| tracing::warn!(error = %err, "Skipping unparseable host_interface_id"),
+                )
                 .ok()?;
             Some(::rpc::forge::LastDhcpRequest {
                 host_interface_id: Some(id),