diff --git a/.changeset/lazy-sloths-worry.md b/.changeset/lazy-sloths-worry.md new file mode 100644 index 000000000..cb02bf3c9 --- /dev/null +++ b/.changeset/lazy-sloths-worry.md @@ -0,0 +1,5 @@ +--- +'@lagon/serverless': patch +--- + +Trace request id in logs diff --git a/crates/runtime_http/src/headers.rs b/crates/runtime_http/src/headers.rs new file mode 100644 index 000000000..ede58b961 --- /dev/null +++ b/crates/runtime_http/src/headers.rs @@ -0,0 +1,5 @@ +pub const X_FORWARDED_FOR: &str = "x-forwarded-for"; +pub const X_REAL_IP: &str = "x-real-ip"; + +pub const X_LAGON_REGION: &str = "x-lagon-region"; +pub const X_LAGON_ID: &str = "x-lagon-id"; diff --git a/crates/runtime_http/src/lib.rs b/crates/runtime_http/src/lib.rs index efe761ade..cdbe045ea 100644 --- a/crates/runtime_http/src/lib.rs +++ b/crates/runtime_http/src/lib.rs @@ -1,9 +1,11 @@ use anyhow::Result; +mod headers; mod method; mod request; mod response; +pub use headers::*; pub use method::*; pub use request::*; pub use response::*; diff --git a/crates/runtime_http/src/request.rs b/crates/runtime_http/src/request.rs index 90ffc3ad5..653f26b6e 100644 --- a/crates/runtime_http/src/request.rs +++ b/crates/runtime_http/src/request.rs @@ -10,6 +10,8 @@ use lagon_runtime_v8_utils::{ }; use std::{collections::HashMap, str::FromStr}; +use crate::X_LAGON_ID; + use super::{FromV8, IntoV8, Method}; #[derive(Debug)] @@ -159,7 +161,9 @@ impl Request { let mut headers = HashMap::new(); for (key, value) in request.headers().iter() { - headers.insert(key.to_string(), value.to_str().unwrap().to_string()); + if key != X_LAGON_ID { + headers.insert(key.to_string(), value.to_str().unwrap().to_string()); + } } let method = Method::from(request.method()); diff --git a/crates/serverless/src/main.rs b/crates/serverless/src/main.rs index 90caf8988..74265c436 100644 --- a/crates/serverless/src/main.rs +++ b/crates/serverless/src/main.rs @@ -7,7 +7,9 @@ use hyper::server::conn::AddrStream; use hyper::service::{make_service_fn, service_fn}; use hyper::{Body, Request as HyperRequest, Response as HyperResponse, Server}; use lagon_runtime::{options::RuntimeOptions, Runtime}; -use lagon_runtime_http::{Request, Response, RunResult}; +use lagon_runtime_http::{ + Request, Response, RunResult, X_FORWARDED_FOR, X_LAGON_ID, X_LAGON_REGION, X_REAL_IP, +}; use lagon_runtime_isolate::{options::IsolateOptions, Isolate}; use lagon_runtime_utils::response::{handle_response, ResponseEvent, FAVICON_URL, PAGE_404}; use lagon_runtime_utils::{ @@ -50,23 +52,25 @@ lazy_static! { } pub const POOL_SIZE: usize = 8; -const X_FORWARDED_FOR: &str = "x-forwarded-for"; -const X_LAGON_REGION: &str = "x-lagon-region"; -const X_REAL_IP: &str = "x-real-ip"; -fn handle_error(result: RunResult, deployment_id: &String, labels: &[(&'static str, String); 3]) { +fn handle_error( + result: RunResult, + deployment_id: &String, + request_id: &String, + labels: &[(&'static str, String); 3], +) { match result { RunResult::Timeout => { increment_counter!("lagon_isolate_timeouts", labels); - warn!(deployment = deployment_id; "Function execution timed out") + warn!(deployment = deployment_id, request = request_id; "Function execution timed out") } RunResult::MemoryLimit => { increment_counter!("lagon_isolate_memory_limits", labels); - warn!(deployment = deployment_id; "Function execution memory limit reached") + warn!(deployment = deployment_id, request = request_id; "Function execution memory limit reached") } RunResult::Error(error) => { increment_counter!("lagon_isolate_errors", labels); - error!(deployment = deployment_id; "Function execution error: {}", error); + error!(deployment = deployment_id, request = request_id; "Function execution error: {}", error); } _ => {} }; @@ -82,6 +86,11 @@ async fn handle_request( ) -> Result> { let url = req.uri().to_string(); + let request_id = match req.headers().get(X_LAGON_ID) { + Some(x_lagon_id) => x_lagon_id.to_str().unwrap_or("none").to_string(), + None => String::new(), + }; + let hostname = match req.headers().get(HOST) { Some(hostname) => hostname.to_str()?.to_string(), None => { @@ -90,6 +99,7 @@ async fn handle_request( "reason" => "No hostname", "region" => REGION.clone(), ); + warn!(request = as_debug!(req), ip = ip, request = request_id; "No Host header found in request"); return Ok(Builder::new().status(404).body(PAGE_404.into())?); } @@ -105,6 +115,7 @@ async fn handle_request( "hostname" => hostname.clone(), "region" => REGION.clone(), ); + warn!(request = as_debug!(req), ip = ip, hostname = hostname, request = request_id; "No deployment found for hostname"); return Ok(HyperResponse::builder().status(404).body(PAGE_404.into())?); } @@ -117,12 +128,13 @@ async fn handle_request( "hostname" => hostname.clone(), "region" => REGION.clone(), ); - warn!(request = as_debug!(req), ip = ip, hostname = hostname; "Cron deployment cannot be called directly"); + warn!(request = as_debug!(req), ip = ip, hostname = hostname, request = request_id; "Cron deployment cannot be called directly"); return Ok(HyperResponse::builder().status(404).body(PAGE_404.into())?); } let deployment_id = deployment.id.clone(); + let request_id_handle = request_id.clone(); let thread_ids_reader = thread_ids.read().await; let thread_id = match thread_ids_reader.get(&hostname) { @@ -162,7 +174,7 @@ async fn handle_request( let run_result = match handle_asset(root, asset) { Ok(response) => RunResult::Response(response), Err(error) => { - error!(deployment = &deployment.id, asset = asset; "Error while handing asset: {}", error); + error!(deployment = &deployment.id, asset = asset, request = request_id; "Error while handing asset: {}", error); RunResult::Error("Could not retrieve asset.".into()) } @@ -181,7 +193,7 @@ async fn handle_request( let mut request = match Request::from_hyper(req).await { Ok(request) => request, Err(error) => { - error!(deployment = &deployment.id; "Error while parsing request: {}", error); + error!(deployment = &deployment.id, request = request_id; "Error while parsing request: {}", error); tx.send_async(RunResult::Error( "Error while parsing request".into(), @@ -211,11 +223,11 @@ async fn handle_request( let isolate = thread_isolates.entry(hostname).or_insert_with(|| { increment_gauge!("lagon_isolates", 1.0, &thread_labels); - info!(deployment = deployment.id, function = deployment.function_id; "Creating new isolate"); + info!(deployment = deployment.id, function = deployment.function_id, request = request_id; "Creating new isolate"); // TODO: handle read error let code = deployment.get_code().unwrap_or_else(|error| { - error!(deployment = deployment.id; "Error while getting deployment code: {}", error); + error!(deployment = deployment.id, request = request_id; "Error while getting deployment code: {}", error); "".into() }); @@ -270,8 +282,8 @@ async fn handle_request( handle_response( rx, - (deployment_id, labels), - Box::new(|event, (deployment_id, labels)| match event { + (deployment_id, request_id_handle, labels), + Box::new(|event, (deployment_id, request_id, labels)| match event { ResponseEvent::Bytes(bytes) => { counter!("lagon_bytes_out", bytes as u64, &labels); } @@ -279,6 +291,7 @@ async fn handle_request( handle_error( RunResult::Error("The stream was done before sending a response/data".into()), &deployment_id, + &request_id, &labels, ); } @@ -286,13 +299,14 @@ async fn handle_request( handle_error( RunResult::Error("Got data after stream was done".into()), &deployment_id, + &request_id, &labels, ); } ResponseEvent::UnexpectedStreamResult(result) | ResponseEvent::LimitsReached(result) | ResponseEvent::Error(result) => { - handle_error(result, &deployment_id, &labels); + handle_error(result, &deployment_id, &request_id, &labels); } }), )