Merge pull request #2398 from calebschoepp/trace-all-the-things

feat(*): Add tracing to some more host components

Author: calebschoepp

Cargo.lock

@@ -134,6 +134,10 @@ wasmtime-wasi-http = "18.0.1"
 
 spin-componentize = { path = "crates/componentize" }
 
+[workspace.lints.clippy]
+# TODO: Remove this once https://github.com/rust-lang/rust-clippy/issues/12281 is resolved
+blocks_in_conditions = "allow"
+
 [[bin]]
 name = "spin"
 path = "src/bin/spin.rs"

Cargo.toml

@@ -13,3 +13,7 @@ spin-key-value = { path = "../key-value" }
 spin-core = { path = "../core" }
 tokio = "1"
 url = "2"
+tracing = { workspace = true }
+
+[lints]
+workspace = true

crates/key-value-azure/Cargo.toml

@@ -9,6 +9,7 @@ use futures::StreamExt;
 use serde::{Deserialize, Serialize};
 use spin_core::async_trait;
 use spin_key_value::{log_error, Error, Store, StoreManager};
+use tracing::{instrument, Level};
 
 pub struct KeyValueAzureCosmos {
     client: CollectionClient,
@@ -46,11 +47,13 @@ struct AzureCosmosStore {
 
 #[async_trait]
 impl Store for AzureCosmosStore {
+    #[instrument(name = "spin_key_value_azure.get", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn get(&self, key: &str) -> Result<Option<Vec<u8>>, Error> {
         let pair = self.get_pair(key).await?;
         Ok(pair.map(|p| p.value))
     }
 
+    #[instrument(name = "spin_key_value_azure.set", skip(self, value), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn set(&self, key: &str, value: &[u8]) -> Result<(), Error> {
         let pair = Pair {
             id: key.to_string(),
@@ -64,6 +67,7 @@ impl Store for AzureCosmosStore {
         Ok(())
     }
 
+    #[instrument(name = "spin_key_value_azure.delete", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn delete(&self, key: &str) -> Result<(), Error> {
         if self.exists(key).await? {
             let document_client = self.client.document_client(key, &key).map_err(log_error)?;
@@ -72,10 +76,12 @@ impl Store for AzureCosmosStore {
         Ok(())
     }
 
+    #[instrument(name = "spin_key_value_azure.exists", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn exists(&self, key: &str) -> Result<bool, Error> {
         Ok(self.get_pair(key).await?.is_some())
     }
 
+    #[instrument(name = "spin_key_value_azure.get_keys", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn get_keys(&self) -> Result<Vec<String>, Error> {
         self.get_keys().await
     }

crates/key-value-azure/src/lib.rs

@@ -11,4 +11,8 @@ spin-key-value = { path = "../key-value" }
 spin-core = { path = "../core" }
 spin-world = { path = "../world" }
 tokio = "1"
-url = "2"
+url = "2"
+tracing = { workspace = true }
+
+[lints]
+workspace = true

crates/key-value-redis/Cargo.toml

@@ -4,6 +4,7 @@ use spin_core::async_trait;
 use spin_key_value::{log_error, Error, Store, StoreManager};
 use std::sync::Arc;
 use tokio::sync::{Mutex, OnceCell};
+use tracing::{instrument, Level};
 use url::Url;
 
 pub struct KeyValueRedis {
@@ -24,6 +25,7 @@ impl KeyValueRedis {
 
 #[async_trait]
 impl StoreManager for KeyValueRedis {
+    #[instrument(name = "spin_key_value_redis.get_store", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn get(&self, _name: &str) -> Result<Arc<dyn Store>, Error> {
         let connection = self
             .connection
@@ -53,11 +55,13 @@ struct RedisStore {
 
 #[async_trait]
 impl Store for RedisStore {
+    #[instrument(name = "spin_key_value_redis.get", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn get(&self, key: &str) -> Result<Option<Vec<u8>>, Error> {
         let mut conn = self.connection.lock().await;
         conn.get(key).await.map_err(log_error)
     }
 
+    #[instrument(name = "spin_key_value_redis.set", skip(self, value), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn set(&self, key: &str, value: &[u8]) -> Result<(), Error> {
         self.connection
             .lock()
@@ -67,6 +71,7 @@ impl Store for RedisStore {
             .map_err(log_error)
     }
 
+    #[instrument(name = "spin_key_value_redis.delete", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn delete(&self, key: &str) -> Result<(), Error> {
         self.connection
             .lock()
@@ -76,6 +81,7 @@ impl Store for RedisStore {
             .map_err(log_error)
     }
 
+    #[instrument(name = "spin_key_value_redis.exists", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn exists(&self, key: &str) -> Result<bool, Error> {
         self.connection
             .lock()
@@ -85,6 +91,7 @@ impl Store for RedisStore {
             .map_err(log_error)
     }
 
+    #[instrument(name = "spin_key_value_redis.get_keys", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn get_keys(&self) -> Result<Vec<String>, Error> {
         self.connection
             .lock()

crates/key-value-redis/src/lib.rs

@@ -12,3 +12,7 @@ tokio = "1"
 spin-key-value = { path = "../key-value" }
 spin-core = { path = "../core" }
 spin-world = { path = "../world" }
+tracing = { workspace = true }
+
+[lints]
+workspace = true

crates/key-value-sqlite/Cargo.toml

@@ -8,6 +8,7 @@ use std::{
     sync::{Arc, Mutex},
 };
 use tokio::task;
+use tracing::{instrument, Level};
 
 pub enum DatabaseLocation {
     InMemory,
@@ -30,6 +31,7 @@ impl KeyValueSqlite {
 
 #[async_trait]
 impl StoreManager for KeyValueSqlite {
+    #[instrument(name = "spin_key_value_sqlite.get_store", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn get(&self, name: &str) -> Result<Arc<dyn Store>, Error> {
         let connection = task::block_in_place(|| {
             self.connection.get_or_try_init(|| {
@@ -74,6 +76,7 @@ struct SqliteStore {
 
 #[async_trait]
 impl Store for SqliteStore {
+    #[instrument(name = "spin_key_value_sqlite.get", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn get(&self, key: &str) -> Result<Option<Vec<u8>>, Error> {
         task::block_in_place(|| {
             self.connection
@@ -89,6 +92,7 @@ impl Store for SqliteStore {
         })
     }
 
+    #[instrument(name = "spin_key_value_sqlite.set", skip(self, value), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn set(&self, key: &str, value: &[u8]) -> Result<(), Error> {
         task::block_in_place(|| {
             self.connection
@@ -105,6 +109,7 @@ impl Store for SqliteStore {
         })
     }
 
+    #[instrument(name = "spin_key_value_sqlite.delete", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn delete(&self, key: &str) -> Result<(), Error> {
         task::block_in_place(|| {
             self.connection
@@ -118,10 +123,12 @@ impl Store for SqliteStore {
         })
     }
 
+    #[instrument(name = "spin_key_value_sqlite.exists", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn exists(&self, key: &str) -> Result<bool, Error> {
         Ok(self.get(key).await?.is_some())
     }
 
+    #[instrument(name = "spin_key_value_sqlite.get_keys", skip(self), err(level = Level::INFO), fields(otel.kind = "client"))]
     async fn get_keys(&self) -> Result<Vec<String>, Error> {
         task::block_in_place(|| {
             self.connection

crates/key-value-sqlite/src/lib.rs

@@ -11,6 +11,7 @@ use tokio::{
     sync::Mutex as AsyncMutex,
     task::{self, JoinHandle},
 };
+use tracing::Instrument;
 
 const DEFAULT_CACHE_SIZE: usize = 256;
 
@@ -74,7 +75,7 @@ impl StoreManager for DelegatingStoreManager {
 /// instances.
 ///
 /// Note that, because writes are asynchronous and return immediately, durability is _not_ guaranteed.  I/O errors
-/// may occur asyncronously after the write operation has returned control to the guest, which may result in the
+/// may occur asynchronously after the write operation has returned control to the guest, which may result in the
 /// write being lost without the guest knowing.  In the future, a separate `write-durable` function could be added
 /// to key-value.wit to provide either synchronous or asynchronous feedback on durability for guests which need it.
 pub struct CachingStoreManager<T> {
@@ -119,15 +120,16 @@ impl CachingStoreState {
     /// the result.  This ensures that write order is preserved.
     fn spawn(&mut self, task: impl Future<Output = Result<(), Error>> + Send + 'static) {
         let previous_task = self.previous_task.take();
-        self.previous_task = Some(task::spawn(async move {
+        let task = async move {
             if let Some(previous_task) = previous_task {
                 previous_task
                     .await
                     .map_err(|e| Error::Other(format!("{e:?}")))??
             }
 
             task.await
-        }))
+        };
+        self.previous_task = Some(task::spawn(task.in_current_span()))
     }
 
     async fn flush(&mut self) -> Result<(), Error> {

crates/key-value/src/util.rs

@@ -31,3 +31,6 @@ tracing = { workspace = true }
 default = []
 metal = ["llm/metal"]
 cublas = ["llm/cublas"]
+
+[lints]
+workspace = true