refactor(serverless): add more context to logs (#239)

* refactor(serverless): add logs context

* chore: add changeset

.changeset/flat-nails-hunt.md

@@ -0,0 +1,5 @@
+---
+'@lagon/serverless': patch
+---
+
+Add more context to logs

packages/serverless/Cargo.toml

@@ -16,7 +16,7 @@ redis = { version = "0.21.6", features = ["tls"] }
 serde_json = "1.0"
 metrics = "0.20.1"
 metrics-exporter-prometheus = { version = "0.11.0", features = ["http-listener"] }
-log = { version = "0.4.17", features = ["std"] }
+log = { version = "0.4.17", features = ["std", "kv_unstable", "kv_unstable_serde"] }
 axiom-rs = "0.6.0"
 chrono = "0.4.22"
 lazy_static = "1.4.0"

packages/serverless/src/deployments/filesystem.rs

@@ -1,3 +1,4 @@
+use std::fs::File;
 use std::io::Write;
 use std::path::PathBuf;
 use std::{env, fs, path::Path};
@@ -34,11 +35,10 @@ pub fn get_deployment_code(deployment: &Deployment) -> Result<String> {
 }
 
 pub fn write_deployment(deployment_id: &str, buf: &[u8]) -> Result<()> {
-    let mut file =
-        fs::File::create(Path::new("deployments").join(deployment_id.to_owned() + ".js"))?;
+    let mut file = File::create(Path::new("deployments").join(deployment_id.to_owned() + ".js"))?;
 
     file.write_all(buf)?;
-    info!("Wrote deployment: {}", deployment_id);
+    info!(deployment = deployment_id; "Wrote deployment");
 
     Ok(())
 }
@@ -53,10 +53,10 @@ pub fn write_deployment_asset(deployment_id: &str, asset: &str, buf: &[u8]) -> R
     fs::create_dir_all(dir)?;
 
     let mut file =
-        fs::File::create(Path::new("deployments").join(deployment_id.to_owned() + "/" + asset))?;
+        File::create(Path::new("deployments").join(deployment_id.to_owned() + "/" + asset))?;
 
     file.write_all(buf)?;
-    info!("Wrote deployment ({}) asset: {}", deployment_id, asset);
+    info!(deployment = deployment_id, asset = asset; "Wrote deployment asset");
 
     Ok(())
 }
@@ -66,7 +66,7 @@ pub fn rm_deployment(deployment_id: &str) -> Result<()> {
 
     // It's possible that the folder doesn't exists if the deployment has no assets
     fs::remove_dir_all(Path::new("deployments").join(deployment_id)).unwrap_or(());
-    info!("Deleted deployment: {}", deployment_id);
+    info!(deployment = deployment_id; "Deleted deployment");
 
     Ok(())
 }

packages/serverless/src/deployments/mod.rs

@@ -152,9 +152,9 @@ pub async fn get_deployments(
         for deployment in deployments_list {
             if !has_deployment_code(&deployment) {
                 if let Err(error) = download_deployment(&deployment, &bucket).await {
-                    error!(
-                        "Failed to download deployment ({}): {:?}",
-                        deployment.id, error
+                    error!(deployment = deployment.id;
+                        "Failed to download deployment: {:?}",
+                        error
                     );
                 }
             }

packages/serverless/src/deployments/pubsub.rs

@@ -1,7 +1,7 @@
 use std::{collections::HashMap, sync::Arc};
 
 use anyhow::Result;
-use log::error;
+use log::{error, warn};
 use s3::Bucket;
 use serde_json::Value;
 use tokio::{sync::RwLock, task::JoinHandle};
@@ -82,10 +82,10 @@ pub fn listen_pub_sub(
 
                             clear_deployments_cache(&domains).await;
                         }
-                        Err(err) => {
+                        Err(error) => {
                             error!(
-                                "Failed to download deployment ({}): {:?}",
-                                deployment.id, err
+                                deployment = deployment.id;
+                                "Failed to download deployment: {}", error
                             );
                         }
                     };
@@ -102,8 +102,8 @@ pub fn listen_pub_sub(
 
                             clear_deployments_cache(&domains).await;
                         }
-                        Err(err) => {
-                            error!("Failed to delete deployment ({}): {:?}", deployment.id, err);
+                        Err(error) => {
+                            error!(deployment = deployment.id; "Failed to delete deployment: {}", error);
                         }
                     };
                 }
@@ -132,7 +132,7 @@ pub fn listen_pub_sub(
 
                     clear_deployments_cache(&domains).await;
                 }
-                _ => error!("Unknown channel: {}", channel),
+                _ => warn!("Unknown channel: {}", channel),
             };
         }
     })

packages/serverless/src/logger.rs

@@ -5,10 +5,13 @@ use serde_json::{json, Value};
 use std::sync::{Arc, RwLock};
 
 use log::{
-    set_boxed_logger, set_max_level, Level, LevelFilter, Log, Metadata, Record, SetLoggerError,
+    as_debug, kv::source::as_map, set_boxed_logger, set_max_level, Level, LevelFilter, Log,
+    Metadata, Record, SetLoggerError,
 };
+
 struct SimpleLogger {
     tx: Arc<RwLock<Option<Sender<Value>>>>,
+    region: String,
 }
 
 impl SimpleLogger {
@@ -33,6 +36,7 @@ impl SimpleLogger {
 
         Self {
             tx: Arc::new(RwLock::new(Some(tx))),
+            region: dotenv::var("LAGON_REGION").expect("LAGON_REGION must be set"),
         }
     }
 }
@@ -44,17 +48,27 @@ impl Log for SimpleLogger {
 
     fn log(&self, record: &Record) {
         if self.enabled(record.metadata()) {
-            println!("{} - {} - {}", Local::now(), record.level(), record.args());
+            let metadata = as_map(record.key_values());
+
+            println!(
+                "{} - {} - {} - {}",
+                Local::now(),
+                record.level(),
+                record.args(),
+                as_debug!(metadata),
+            );
 
             // Axiom is optional, so tx can have no listeners
             let tx = self.tx.read().expect("Tx lock is poisoned");
+
             if let Some(tx) = &*tx {
                 if !tx.is_disconnected() {
                     tx.send(json!({
-                        "region": dotenv::var("LAGON_REGION").expect("LAGON_REGION must be set"),
+                        "region": self.region,
                         "_time": Local::now().to_rfc3339(),
                         "level": record.level().to_string(),
                         "message": record.args().to_string(),
+                        "metadata": metadata,
                     }))
                     .unwrap_or(())
                 }

packages/serverless/src/main.rs

@@ -10,7 +10,7 @@ use lagon_runtime::http::{Request, RunResult, StreamResult};
 use lagon_runtime::isolate::{Isolate, IsolateOptions};
 use lagon_runtime::runtime::{Runtime, RuntimeOptions};
 use lazy_static::lazy_static;
-use log::{error, info};
+use log::{as_debug, error, info, warn};
 use lru_time_cache::LruCache;
 use metrics::increment_counter;
 use metrics_exporter_prometheus::PrometheusBuilder;
@@ -67,7 +67,11 @@ async fn handle_request(
 
     let hostname = match req.headers().get(HOST) {
         Some(hostname) => hostname.to_str()?.to_string(),
-        None => return Ok(Builder::new().status(404).body(PAGE_404.into())?),
+        None => {
+            warn!(request = as_debug!(req); "No hostname found in request");
+
+            return Ok(Builder::new().status(404).body(PAGE_404.into())?);
+        }
     };
 
     let thread_ids_reader = thread_ids.read().await;
@@ -107,10 +111,7 @@ async fn handle_request(
                             let run_result = match handle_asset(deployment, asset) {
                                 Ok(response) => RunResult::Response(response),
                                 Err(error) => {
-                                    error!(
-                                        "Error while handing asset ({}, {}): {}",
-                                        asset, deployment.id, error
-                                    );
+                                    error!(deployment = &deployment.id, asset = asset; "Error while handing asset: {}", error);
 
                                     RunResult::Error("Could not retrieve asset.".into())
                                 }
@@ -121,10 +122,7 @@ async fn handle_request(
                             let maybe_request = Request::from_hyper(req).await;
 
                             if let Err(error) = maybe_request {
-                                error!(
-                                    "Error while parsing request ({}): {}",
-                                    deployment.id, error
-                                );
+                                error!(deployment = &deployment.id; "Error while parsing request: {}", error);
 
                                 tx.send_async(RunResult::Error(
                                     "Error while parsing request".into(),
@@ -148,7 +146,8 @@ async fn handle_request(
                             });
 
                             let isolate = thread_isolates.entry(hostname).or_insert_with(|| {
-                                info!("Creating new isolate: {} ", deployment.id);
+                                info!(deployment = deployment.id; "Creating new isolate");
+
                                 // TODO: handle read error
                                 let code = get_deployment_code(deployment).unwrap();
                                 let options = IsolateOptions::new(code)
@@ -159,7 +158,7 @@ async fn handle_request(
                                     .with_timeout(deployment.timeout)
                                     .with_id(deployment.id.clone())
                                     .with_on_drop_callback(Box::new(|id| {
-                                        info!("Dropping isolate: {}", id.unwrap());
+                                        info!(deployment = &id.unwrap(); "Dropping isolate");
                                     }));
 
                                 Isolate::new(options)