functional tracing

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<Mutex<Vec<BrowserHolder>>> = 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
                 }
             }

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<S> {
+    //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<S>() -> impl tracing_subscriber::Layer<S>
+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<Build> {
+    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,
         ])

src/routes/mod.rs

@@ -1 +1 @@
-pub mod pdf;
+pub mod pdf;

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/<username>/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")
 }

src/tools/mod.rs

@@ -0,0 +1 @@
+pub mod rocket;

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<T = String>(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<Self, ()> {
+        match &*request.local_cache(|| RequestId::<Option<String>>(None)) {
+            RequestId(Some(request_id)) => Outcome::Success(RequestId(request_id.to_owned())),
+            RequestId(None) => request::Outcome::Error((Status::InternalServerError, ())),
+        }
+    }
+}
+
+#[derive(Clone)]
+pub struct TracingSpan<T = Span>(
+    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::<Option<Span>>(Some(span)));
+    }
+
+    async fn on_response<'r>(&self, req: &'r Request<'_>, res: &mut Response<'r>) {
+        if let Some(span) = req.local_cache(|| TracingSpan::<Option<Span>>(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::<Option<String>>(None)).0 {
+                info!("Returning request {} with {}", request_id, res.status());
+            }
+
+            drop(_entered_span);
+        }
+
+        if let Some(request_id) = &req.local_cache(|| RequestId::<Option<String>>(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<Self, ()> {
+        match &*request.local_cache(|| TracingSpan::<Option<Span>>(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<SystemTime>);
+
+#[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<Self, ()> {
+        match *request.local_cache(|| TimerStart(None)) {
+            TimerStart(Some(time)) => request::Outcome::Success(StartTime(time)),
+            TimerStart(None) => request::Outcome::Error((Status::InternalServerError, ())),
+        }
+    }
+}