diff --git a/Cargo.lock b/Cargo.lock index 729b1f0..41e8b2e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -266,6 +266,25 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "crossbeam-channel" +version = "0.5.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a33c2bf77f2df06183c3aa30d1e96c0695a313d4f9c453cc3762a6db39f99200" +dependencies = [ + "cfg-if", + "crossbeam-utils", +] + +[[package]] +name = "crossbeam-utils" +version = "0.8.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5a22b2d63d4d1dc0b7f1b6b2747dd0088008a9be28b6ddf0b1e7d335e3037294" +dependencies = [ + "cfg-if", +] + [[package]] name = "crypto-common" version = "0.1.6" @@ -521,12 +540,34 @@ version = "0.3.29" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "eb1d22c66e66d9d72e1758f0bd7d4fd0bee04cad842ee34587d68c07e45d088c" +[[package]] +name = "futures-executor" +version = "0.3.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0f4fb8693db0cf099eadcca0efe2a5a22e4550f98ed16aba6c48700da29597bc" +dependencies = [ + "futures-core", + "futures-task", + "futures-util", +] + [[package]] name = "futures-io" version = "0.3.29" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8bf34a163b5c4c52d0478a4d757da8fb65cabef42ba90515efee0f6f9fa45aaa" +[[package]] +name = "futures-macro" +version = "0.3.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "53b153fd91e4b0147f4aced87be237c98248656bb01050b96bf3ee89220a8ddb" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.39", +] + [[package]] name = "futures-sink" version = "0.3.29" @@ -548,6 +589,7 @@ dependencies = [ "futures-channel", "futures-core", "futures-io", + "futures-macro", "futures-sink", "futures-task", "memchr", @@ -959,6 +1001,66 @@ version = "1.18.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "dd8b5dd2ae5ed71462c540258bedcb51965123ad7e7ccf4b9a8cafaa4a63576d" +[[package]] +name = "opentelemetry" +version = "0.21.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1e32339a5dc40459130b3bd269e9892439f55b33e772d2a9d402a789baaf4e8a" +dependencies = [ + "futures-core", + "futures-sink", + "indexmap", + "js-sys", + "once_cell", + "pin-project-lite", + "thiserror", + "urlencoding", +] + +[[package]] +name = "opentelemetry-stdout" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c13b2df4cd59c176099ac82806725ba340c8fa7b1a7004c0912daad30470f63e" +dependencies = [ + "chrono", + "futures-util", + "opentelemetry", + "opentelemetry_sdk", + "ordered-float", + "serde", + "serde_json", +] + +[[package]] +name = "opentelemetry_sdk" +version = "0.21.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "968ba3f2ca03e90e5187f5e4f46c791ef7f2c163ae87789c8ce5f5ca3b7b7de5" +dependencies = [ + "async-trait", + "crossbeam-channel", + "futures-channel", + "futures-executor", + "futures-util", + "glob", + "once_cell", + "opentelemetry", + "ordered-float", + "percent-encoding", + "rand", + "thiserror", +] + +[[package]] +name = "ordered-float" +version = "4.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "536900a8093134cf9ccf00a27deb3532421099e958d9dd431135d0c7543ca1e8" +dependencies = [ + "num-traits", +] + [[package]] name = "overload" version = "0.1.1" @@ -984,11 +1086,21 @@ dependencies = [ "fern", "headless_chrome", "log", + "opentelemetry", + "opentelemetry-stdout", + "opentelemetry_sdk", "ovlach_data", "rocket", "serde", "serde_yaml", "tokio", + "tracing", + "tracing-appender", + "tracing-log", + "tracing-opentelemetry", + "tracing-subscriber", + "uuid", + "yansi 0.5.1", ] [[package]] @@ -1022,7 +1134,7 @@ checksum = "61a386cd715229d399604b50d1361683fe687066f42d56f54be995bc6868f71c" dependencies = [ "inlinable_string", "pear_codegen", - "yansi", + "yansi 1.0.0-rc.1", ] [[package]] @@ -1086,7 +1198,7 @@ dependencies = [ "quote", "syn 2.0.39", "version_check", - "yansi", + "yansi 1.0.0-rc.1", ] [[package]] @@ -1250,7 +1362,7 @@ dependencies = [ "tokio-util", "ubyte", "version_check", - "yansi", + "yansi 1.0.0-rc.1", ] [[package]] @@ -1744,6 +1856,18 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3566e8ce28cc0a3fe42519fc80e6b4c943cc4c8cef275620eb8dac2d3d4e06cf" +dependencies = [ + "crossbeam-channel", + "thiserror", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.27" @@ -1776,6 +1900,34 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-opentelemetry" +version = "0.22.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c67ac25c5407e7b961fafc6f7e9aa5958fd297aada2d20fa2ae1737357e55596" +dependencies = [ + "js-sys", + "once_cell", + "opentelemetry", + "opentelemetry_sdk", + "smallvec", + "tracing", + "tracing-core", + "tracing-log", + "tracing-subscriber", + "web-time", +] + +[[package]] +name = "tracing-serde" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.18" @@ -1786,12 +1938,15 @@ dependencies = [ "nu-ansi-term", "once_cell", "regex", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] @@ -1911,12 +2066,27 @@ dependencies = [ "percent-encoding", ] +[[package]] +name = "urlencoding" +version = "2.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "daf8dba3b7eb870caf1ddeed7bc9d2a049f3cfdfae7cb521b087cc33ae4c49da" + [[package]] name = "utf-8" version = "0.7.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "09cc8ee72d2a9becf2f2febe0205bbed8fc6615b7cb429ad062dc7b7ddd036a9" +[[package]] +name = "uuid" +version = "1.6.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5e395fcf16a7a3d8127ec99782007af141946b4795001f876d54fb0d55978560" +dependencies = [ + "getrandom", +] + [[package]] name = "valuable" version = "0.1.0" @@ -1998,6 +2168,16 @@ version = "0.2.89" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7ab9b36309365056cd639da3134bf87fa8f3d86008abf99e612384a6eecd459f" +[[package]] +name = "web-time" +version = "0.2.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "57099a701fb3a8043f993e8228dc24229c7b942e2b009a1b962e54489ba1d3bf" +dependencies = [ + "js-sys", + "wasm-bindgen", +] + [[package]] name = "webpki-roots" version = "0.25.3" @@ -2142,6 +2322,12 @@ dependencies = [ "windows-sys", ] +[[package]] +name = "yansi" +version = "0.5.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "09041cd90cf85f7f8b2df60c646f853b7f535ce68f85244eb6731cf89fa498ec" + [[package]] name = "yansi" version = "1.0.0-rc.1" diff --git a/Cargo.toml b/Cargo.toml index fb1e188..257ec7a 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -16,4 +16,17 @@ headless_chrome = "1.0.8" ovlach_data = { git = "ssh://git@gitlab.nanobyte.cz/ondrej/ov-site-api-data.git", branch = "add_missing_fields"} async-trait = "0.1.74" async-mutex = "1.4.0" -tokio = { version = "1.34.0", features = ["macros"] } \ No newline at end of file +tokio = { version = "1.34.0", features = ["macros"] } + + + +tracing = "0.1.37" +tracing-appender = "0.2.2" +tracing-log = "0.2.0" +tracing-subscriber = {version="0.3.17", features=["env-filter", "json", "registry", "smallvec"]} +tracing-opentelemetry = "0.22.0" +opentelemetry = "0.21" +opentelemetry_sdk = "0.21" +opentelemetry-stdout = { version = "0.2.0", features = ["trace"] } +uuid = {version="1.4.1", features = ["v4"]} +yansi = "0.5.1" \ No newline at end of file diff --git a/src/chromium/rocket.rs b/src/chromium/rocket.rs index 3e12f7e..96deae2 100644 --- a/src/chromium/rocket.rs +++ b/src/chromium/rocket.rs @@ -2,7 +2,7 @@ use std::{sync::Arc, time::Duration}; use async_trait::async_trait; use async_mutex::Mutex; use headless_chrome::{Browser, LaunchOptions}; -use log::{error, info}; +use tracing::{error, info, debug, trace, warn}; use rocket::{fairing::{Fairing, self}, Rocket, Build, Request, request::{FromRequest, Outcome}, futures::pin_mut, http::Status}; use tokio::time::sleep; @@ -45,9 +45,11 @@ impl ChromiumCoordinator { pub async fn new() -> Self { let instances: Arc>> = Arc::new(Mutex::new(Vec::with_capacity(Self::NUMBER_OF_INSTANCES))); + trace!("creating {} Chromium instances", Self::NUMBER_OF_INSTANCES); while instances.lock().await.len() < Self::NUMBER_OF_INSTANCES { instances.lock().await.push(Self::create_browser_instance()); } + trace!("done creating {} Chromium instances", Self::NUMBER_OF_INSTANCES); Self { instances } } @@ -62,9 +64,10 @@ impl ChromiumCoordinator { fn spawn_browser(&self) { let instances = self.instances.clone(); tokio::spawn(async move { - info!("Spawn new instance of browser"); + debug!("spawn new instance of browser"); // Create new instance instances.lock().await.push(Self::create_browser_instance()); + debug!("spawned new instance of browser"); }); } @@ -94,7 +97,10 @@ impl ChromiumCoordinator { let browser = self.loop_get_instance().await; match browser.browser.get_version() { Ok(_) => Ok(browser), - Err(_) => Err(()), + Err(_) => { + warn!("found dead browser instance"); + Err(()) + }, } } @@ -103,6 +109,7 @@ impl ChromiumCoordinator { match self.try_get_browser().await { Ok(browser) => return Ok(browser), Err(_) => { + trace!("all instances of browser are dead... waiting for "); // all instances may be dead ... we must wait for new instance } } diff --git a/src/lib.rs b/src/lib.rs index 392e7df..87b2260 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,12 +1,110 @@ use chromium::rocket::Chromium; use rocket::{Rocket, Build, routes}; - +use tools::rocket::TracingFairing; +use tracing_subscriber::EnvFilter; +use tracing_subscriber::prelude::*; pub mod routes; mod chromium; +mod tools; + + +use rocket::http::Status; +use rocket::request::FromRequest; +use rocket::request::Outcome; +use rocket::serde::{json::Json, Serialize}; +use rocket::{ + fairing::{Fairing, Info, Kind}, + Data, Request, Response, +}; + + +use tracing::{info_span, Span}; +use tracing_log::LogTracer; + +use tracing_subscriber::registry::LookupSpan; +use uuid::Uuid; +use yansi::Paint; + + +#[derive(PartialEq, Eq, Debug, Clone, Copy)] +pub enum LogLevel { + /// Only shows errors and warnings: `"critical"`. + Critical, + /// Shows errors, warnings, and some informational messages that are likely + /// to be relevant when troubleshooting such as configuration: `"support"`. + Support, + /// Shows everything except debug and trace information: `"normal"`. + Normal, + /// Shows everything: `"debug"`. + Debug, + /// Shows nothing: "`"off"`". + Off, +} + + +pub fn filter_layer(level: LogLevel) -> EnvFilter { + let filter_str = match level { + LogLevel::Critical => "warn,hyper=off,rustls=off", + LogLevel::Support => "warn,rocket::support=info,hyper=off,rustls=off", + LogLevel::Normal => "info,hyper=off,rustls=off", + LogLevel::Debug => "trace", + LogLevel::Off => "off", + }; + + tracing_subscriber::filter::EnvFilter::try_new(filter_str).expect("filter string must parse") +} + + +pub fn json_logging_layer< + S: for<'a> tracing_subscriber::registry::LookupSpan<'a> + tracing::Subscriber, +>() -> impl tracing_subscriber::Layer { + //Paint::disable(); + + tracing_subscriber::fmt::layer() + .json() + // Configure the formatter to use `print!` rather than + // `stdout().write_str(...)`, so that logs are captured by libtest's test + // capturing. + .with_test_writer() +} + + +pub fn default_logging_layer() -> impl tracing_subscriber::Layer +where + S: tracing::Subscriber, + S: for<'span> LookupSpan<'span>, +{ + let field_format = tracing_subscriber::fmt::format::debug_fn(|writer, field, value| { + // We'll format the field name and value separated with a colon. + if field.name() == "message" { + write!(writer, "{:?}", Paint::new(value).bold()) + } else { + write!(writer, "{}: {:?}", field, Paint::default(value).bold()) + } + }) + .delimited(", ") + .display_messages(); + + tracing_subscriber::fmt::layer() + .fmt_fields(field_format) + // Configure the formatter to use `print!` rather than + // `stdout().write_str(...)`, so that logs are captured by libtest's test + // capturing. + .with_test_writer() +} + pub fn rocket_builder() -> Rocket { + tracing::subscriber::set_global_default( + tracing_subscriber::registry() + .with(default_logging_layer()) + .with(filter_layer(LogLevel::Debug)), + ) + .unwrap(); rocket::build() + .attach(TracingFairing {}) .attach(Chromium::ignite()) + .attach(tools::rocket::RequestTimer) .mount("/", routes![ routes::pdf::render_pdf_cv, ]) diff --git a/src/routes/mod.rs b/src/routes/mod.rs index 7afe216..0f137f1 100644 --- a/src/routes/mod.rs +++ b/src/routes/mod.rs @@ -1 +1 @@ -pub mod pdf; \ No newline at end of file +pub mod pdf; diff --git a/src/routes/pdf.rs b/src/routes/pdf.rs index 8efe78b..de548e0 100644 --- a/src/routes/pdf.rs +++ b/src/routes/pdf.rs @@ -4,10 +4,11 @@ use std::io::prelude::*; use headless_chrome::Browser; use headless_chrome::{types::PrintToPdfOptions, LaunchOptions}; -use log::error; use rocket::{get, Response, futures::Stream, tokio::net::UnixStream, fs::NamedFile}; +use tracing::{info_span, debug, info}; use crate::chromium::rocket::BrowserHolder; +use crate::tools::rocket::TracingSpan; fn generate_pdf(browser: Browser) { let tab = browser.new_tab().unwrap(); @@ -35,8 +36,19 @@ fn generate_pdf(browser: Browser) { } #[get("/cv//pdf")] -pub async fn render_pdf_cv(username: &str, browser: BrowserHolder) -> NamedFile { +pub async fn render_pdf_cv(username: &str, browser: BrowserHolder, tracing: TracingSpan) -> NamedFile { + let entered_span = tracing.0.enter(); + tracing.0.record( + "username", + username + ); + let span = info_span!("render_pdf", username = username); + let entered_inner_span = span.enter(); + info!("generate PDF"); generate_pdf(browser.browser); + info!("done generating"); + drop(entered_inner_span); + drop(entered_span); "foo!".to_string(); NamedFile::open("/tmp/foo.pdf").await.expect("failed to open foo.pdf") } \ No newline at end of file diff --git a/src/tools/mod.rs b/src/tools/mod.rs new file mode 100644 index 0000000..78211d4 --- /dev/null +++ b/src/tools/mod.rs @@ -0,0 +1 @@ +pub mod rocket; \ No newline at end of file diff --git a/src/tools/rocket.rs b/src/tools/rocket.rs new file mode 100644 index 0000000..6cf4ee5 --- /dev/null +++ b/src/tools/rocket.rs @@ -0,0 +1,170 @@ + +/// Fairing for timing requests. + + +use std::time::SystemTime; +use log::info; + +use rocket::Build; +use rocket::Rocket; +use rocket::fairing; +use rocket::http::Status; +use rocket::request; +use rocket::request::FromRequest; +use rocket::request::Outcome; +use rocket::serde::{json::Json, Serialize}; +use rocket::{ + fairing::{Fairing, Info, Kind}, + Data, Request, Response, +}; + + +use tracing::{info_span, Span}; +use tracing_log::LogTracer; + +use tracing_subscriber::Layer; +use tracing_subscriber::Registry; +use tracing_subscriber::{registry::LookupSpan, EnvFilter}; +use uuid::Uuid; + + +// Test + + +#[derive(Clone, Debug)] +pub struct RequestId(pub T); + +// Allows a route to access the request id +#[rocket::async_trait] +impl<'r> FromRequest<'r> for RequestId { + type Error = (); + + async fn from_request(request: &'r Request<'_>) -> Outcome { + match &*request.local_cache(|| RequestId::>(None)) { + RequestId(Some(request_id)) => Outcome::Success(RequestId(request_id.to_owned())), + RequestId(None) => request::Outcome::Error((Status::InternalServerError, ())), + } + } +} + +#[derive(Clone)] +pub struct TracingSpan( + pub T +); + +pub struct TracingFairing; + +#[rocket::async_trait] +impl Fairing for TracingFairing { + fn info(&self) -> Info { + Info { + name: "Tracing Fairing", + kind: Kind::Request | Kind::Response, + } + } + + async fn on_request(&self, req: &mut Request<'_>, _data: &mut Data<'_>) { + let user_agent = req.headers().get_one("User-Agent").unwrap_or(""); + let request_id = req + .headers() + .get_one("X-Request-Id") + .map(ToString::to_string) + .unwrap_or_else(|| Uuid::new_v4().to_string()); + + req.local_cache(|| RequestId(Some(request_id.to_owned()))); + + let span = info_span!( + "request", + otel.name=%format!("{} {}", req.method(), req.uri().path()), + http.method = %req.method(), + http.uri = %req.uri().path(), + http.user_agent=%user_agent, + http.status_code = tracing::field::Empty, + http.request_id=%request_id + ); + + req.local_cache(|| TracingSpan::>(Some(span))); + } + + async fn on_response<'r>(&self, req: &'r Request<'_>, res: &mut Response<'r>) { + if let Some(span) = req.local_cache(|| TracingSpan::>(None)).0.to_owned() { + let _entered_span = span.entered(); + _entered_span.record("http.status_code", &res.status().code); + + if let Some(request_id) = &req.local_cache(|| RequestId::>(None)).0 { + info!("Returning request {} with {}", request_id, res.status()); + } + + drop(_entered_span); + } + + if let Some(request_id) = &req.local_cache(|| RequestId::>(None)).0 { + res.set_raw_header("X-Request-Id", request_id); + } + } +} + +// Allows a route to access the span +#[rocket::async_trait] +impl<'r> FromRequest<'r> for TracingSpan { + type Error = (); + + async fn from_request(request: &'r Request<'_>) -> Outcome { + match &*request.local_cache(|| TracingSpan::>(None)) { + TracingSpan(Some(span)) => Outcome::Success(TracingSpan(span.to_owned())), + TracingSpan(None) => request::Outcome::Error((Status::InternalServerError, ())), + } + } +} + +pub struct RequestTimer; + +/// Value stored in request-local state. +#[derive(Copy, Clone)] +struct TimerStart(Option); + +#[rocket::async_trait] +impl Fairing for RequestTimer { + fn info(&self) -> Info { + Info { + name: "Request Timer", + kind: Kind::Request | Kind::Response + } + } + + /// Stores the start time of the request in request-local state. + async fn on_request(&self, request: &mut Request<'_>, _: &mut Data<'_>) { + // Store a `TimerStart` instead of directly storing a `SystemTime` + // to ensure that this usage doesn't conflict with anything else + // that might store a `SystemTime` in request-local cache. + request.local_cache(|| TimerStart(Some(SystemTime::now()))); + } + + /// Adds a header to the response indicating how long the server took to + /// process the request. + async fn on_response<'r>(&self, req: &'r Request<'_>, res: &mut Response<'r>) { + let start_time = req.local_cache(|| TimerStart(None)); + if let Some(Ok(duration)) = start_time.0.map(|st| st.elapsed()) { + let ms = duration.as_secs() * 1000 + duration.subsec_millis() as u64; + res.set_raw_header("X-Response-Time", format!("{} ms", ms)); + info!("Response time: {} ms", ms); + } + } +} + +/// Request guard used to retrieve the start time of a request. +#[derive(Copy, Clone)] +pub struct StartTime(pub SystemTime); + +// Allows a route to access the time a request was initiated. +#[rocket::async_trait] +impl<'r> FromRequest<'r> for StartTime { + type Error = (); + + async fn from_request(request: &'r Request<'_>) -> request::Outcome { + match *request.local_cache(|| TimerStart(None)) { + TimerStart(Some(time)) => request::Outcome::Success(StartTime(time)), + TimerStart(None) => request::Outcome::Error((Status::InternalServerError, ())), + } + } +} \ No newline at end of file