use a thread local to store custom metadata

Before this commit, custom metadata was stored as part of a request
extension, which required the mutable request object to be passed to
every place which needed to log something.

This commit changes the implementation to use a thread local that is
cleared before a request is processed. This removes the dependency on
the mutable request object.

Note that when migrating the crates.io codebase to async the thread
local will need to be replaced with an async equivalent.

Author: pietroalbini

src/controllers.rs

@@ -8,8 +8,6 @@ mod frontend_prelude {
     pub use crate::util::errors::{bad_request, server_error};
 }
 
-pub(crate) use prelude::RequestUtils;
-
 mod prelude {
     pub use super::helpers::ok_true;
     pub use diesel::prelude::*;
@@ -36,8 +34,6 @@ mod prelude {
         fn query(&self) -> IndexMap<String, String>;
         fn wants_json(&self) -> bool;
         fn query_with_params(&self, params: IndexMap<String, String>) -> String;
-
-        fn log_metadata<V: std::fmt::Display>(&mut self, key: &'static str, value: V);
     }
 
     impl<'a> RequestUtils for dyn RequestExt + 'a {
@@ -74,10 +70,6 @@ mod prelude {
                 .finish();
             format!("?{query_string}")
         }
-
-        fn log_metadata<V: std::fmt::Display>(&mut self, key: &'static str, value: V) {
-            crate::middleware::log_request::add_custom_metadata(self, key, value);
-        }
     }
 }
 

src/controllers/helpers/pagination.rs

@@ -92,7 +92,7 @@ impl PaginationOptionsBuilder {
                 }
 
                 if numeric_page > MAX_PAGE_BEFORE_SUSPECTED_BOT {
-                    req.log_metadata("bot", "suspected");
+                    add_custom_metadata("bot", "suspected");
                 }
 
                 // Block large offsets for known violators of the crawler policy
@@ -105,7 +105,7 @@ impl PaginationOptionsBuilder {
                             .iter()
                             .any(|blocked| user_agent.contains(blocked))
                     {
-                        add_custom_metadata(req, "cause", "large page offset");
+                        add_custom_metadata("cause", "large page offset");
                         return Err(bad_request("requested page offset is too large"));
                     }
                 }

src/controllers/krate/publish.rs

@@ -16,6 +16,7 @@ use crate::models::{
 };
 use crate::worker;
 
+use crate::middleware::log_request::add_custom_metadata;
 use crate::schema::*;
 use crate::util::errors::{cargo_err, AppResult};
 use crate::util::{read_fill, read_le_u32, CargoVcsInfo, LimitErrorReader, Maximums};
@@ -59,8 +60,8 @@ pub fn publish(req: &mut dyn RequestExt) -> EndpointResult {
 
     let new_crate = parse_new_headers(req)?;
 
-    req.log_metadata("crate_name", new_crate.name.to_string());
-    req.log_metadata("crate_version", new_crate.vers.to_string());
+    add_custom_metadata("crate_name", new_crate.name.to_string());
+    add_custom_metadata("crate_version", new_crate.vers.to_string());
 
     let conn = app.primary_database.get()?;
     let ids = req.authenticate()?;
@@ -265,7 +266,7 @@ pub fn publish(req: &mut dyn RequestExt) -> EndpointResult {
 fn parse_new_headers(req: &mut dyn RequestExt) -> AppResult<EncodableCrateUpload> {
     // Read the json upload request
     let metadata_length = u64::from(read_le_u32(req.body())?);
-    req.log_metadata("metadata_length", metadata_length);
+    add_custom_metadata("metadata_length", metadata_length);
 
     let max = req.app().config.max_upload_size;
     if metadata_length > max {

src/controllers/util.rs

@@ -129,9 +129,9 @@ impl<'a> UserAuthenticationExt for dyn RequestExt + 'a {
             }
         }
 
-        log_request::add_custom_metadata(self, "uid", authenticated_user.user_id());
+        log_request::add_custom_metadata("uid", authenticated_user.user_id());
         if let Some(id) = authenticated_user.api_token_id() {
-            log_request::add_custom_metadata(self, "tokenid", id);
+            log_request::add_custom_metadata("tokenid", id);
         }
 
         Ok(authenticated_user)

src/controllers/version/downloads.rs

@@ -5,6 +5,7 @@
 use super::{extract_crate_name_and_semver, version_and_crate};
 use crate::controllers::prelude::*;
 use crate::db::PoolError;
+use crate::middleware::log_request::add_custom_metadata;
 use crate::models::{Crate, VersionDownload};
 use crate::schema::*;
 use crate::views::EncodableVersionDownload;
@@ -108,7 +109,7 @@ pub fn download(req: &mut dyn RequestExt) -> EndpointResult {
         .crate_location(&crate_name, &*version);
 
     if let Some((key, value)) = log_metadata {
-        req.log_metadata(key, value);
+        add_custom_metadata(key, value);
     }
 
     if req.wants_json() {

src/middleware/balance_capacity.rs

@@ -56,11 +56,11 @@ impl BalanceCapacity {
     fn handle_high_load(&self, request: &mut dyn RequestExt, note: &str) -> AfterResult {
         if self.report_only {
             // In report-only mode we serve all requests but add log metadata
-            add_custom_metadata(request, "would_reject", note);
+            add_custom_metadata("would_reject", note);
             self.handle(request)
         } else {
             // Reject the request
-            add_custom_metadata(request, "cause", note);
+            add_custom_metadata("cause", note);
             let body = "Service temporarily unavailable";
             Response::builder()
                 .status(StatusCode::SERVICE_UNAVAILABLE)
@@ -84,7 +84,7 @@ impl Handler for BalanceCapacity {
 
         // Begin logging total request count so early stages of load increase can be located
         if in_flight_total >= self.log_total_at_count {
-            add_custom_metadata(request, "in_flight_total", in_flight_total);
+            add_custom_metadata("in_flight_total", in_flight_total);
         }
 
         // Download requests are always accepted and do not affect the capacity tracking
@@ -98,7 +98,7 @@ impl Handler for BalanceCapacity {
 
         // Begin logging non-download request count so early stages of non-download load increase can be located
         if load >= self.log_at_percentage {
-            add_custom_metadata(request, "in_flight_non_dl_requests", count);
+            add_custom_metadata("in_flight_non_dl_requests", count);
         }
 
         // Reject read-only requests as load nears capacity. Bots are likely to send only safe

src/middleware/block_traffic.rs

@@ -48,7 +48,7 @@ impl Handler for BlockTraffic {
             .any(|value| self.blocked_values.iter().any(|v| v == value));
         if has_blocked_value {
             let cause = format!("blocked due to contents of header {}", self.header_name);
-            add_custom_metadata(req, "cause", cause);
+            add_custom_metadata("cause", cause);
             let body = format!(
                 "We are unable to process your request at this time. \
                  This usually means that you are in violation of our crawler \

src/middleware/log_request.rs

@@ -8,48 +8,51 @@ use conduit::{header, RequestExt, StatusCode};
 
 use crate::middleware::normalize_path::OriginalPath;
 use crate::middleware::response_timing::ResponseTime;
+use std::cell::RefCell;
 use std::fmt::{self, Display, Formatter};
 
 const SLOW_REQUEST_THRESHOLD_MS: u64 = 1000;
 
+// A thread local is used instead of a request extension to avoid the need to pass the request
+// object everywhere in the codebase. When migrating to async this will need to be moved to an
+// async-equivalent, as thread locals misbehave in async contexes.
+thread_local! {
+    static CUSTOM_METADATA: RefCell<Vec<(&'static str, String)>> = RefCell::new(Vec::new());
+}
+
 #[derive(Default)]
 pub(super) struct LogRequests();
 
 impl Middleware for LogRequests {
+    fn before(&self, _: &mut dyn RequestExt) -> BeforeResult {
+        // Remove any metadata set by the previous task before processing any new request.
+        CUSTOM_METADATA.with(|metadata| metadata.borrow_mut().clear());
+
+        Ok(())
+    }
+
     fn after(&self, req: &mut dyn RequestExt, res: AfterResult) -> AfterResult {
         println!("{}", RequestLine { req, res: &res });
 
         res
     }
 }
 
-struct CustomMetadata {
-    entries: Vec<(&'static str, String)>,
-}
-
-pub fn add_custom_metadata<V: Display>(req: &mut dyn RequestExt, key: &'static str, value: V) {
-    if let Some(metadata) = req.mut_extensions().get_mut::<CustomMetadata>() {
-        metadata.entries.push((key, value.to_string()));
-    } else {
-        let mut metadata = CustomMetadata {
-            entries: Vec::new(),
-        };
-        metadata.entries.push((key, value.to_string()));
-        req.mut_extensions().insert(metadata);
-    }
-
+pub fn add_custom_metadata<V: Display>(key: &'static str, value: V) {
+    CUSTOM_METADATA.with(|metadata| metadata.borrow_mut().push((key, value.to_string())));
     sentry::configure_scope(|scope| scope.set_extra(key, value.to_string().into()));
 }
 
 #[cfg(test)]
-pub(crate) fn get_log_message(req: &dyn RequestExt, key: &'static str) -> String {
-    // Unwrap shouldn't panic as no other code has access to the private struct to remove it
-    for (k, v) in &req.extensions().get::<CustomMetadata>().unwrap().entries {
-        if key == *k {
-            return v.clone();
+pub(crate) fn get_log_message(key: &'static str) -> String {
+    CUSTOM_METADATA.with(|metadata| {
+        for (k, v) in &*metadata.borrow() {
+            if key == *k {
+                return v.clone();
+            }
         }
-    }
-    panic!("expected log message for {} not found", key);
+        panic!("expected log message for {} not found", key);
+    })
 }
 
 struct RequestLine<'r> {
@@ -95,11 +98,12 @@ impl Display for RequestLine<'_> {
         line.add_field("status", status.as_str())?;
         line.add_quoted_field("user_agent", request_header(self.req, header::USER_AGENT))?;
 
-        if let Some(metadata) = self.req.extensions().get::<CustomMetadata>() {
-            for (key, value) in &metadata.entries {
+        CUSTOM_METADATA.with(|metadata| {
+            for (key, value) in &*metadata.borrow() {
                 line.add_quoted_field(key, value)?;
             }
-        }
+            fmt::Result::Ok(())
+        })?;
 
         if let Err(err) = self.res {
             line.add_quoted_field("error", err)?;

src/middleware/normalize_path.rs

@@ -43,7 +43,7 @@ impl Middleware for NormalizePath {
             .to_string_lossy()
             .to_string(); // non-Unicode is replaced with U+FFFD REPLACEMENT CHARACTER
 
-        add_custom_metadata(req, "normalized_path", path.clone());
+        add_custom_metadata("normalized_path", path.clone());
 
         *req.path_mut() = path;
         req.mut_extensions().insert(original_path);

src/middleware/require_user_agent.rs

@@ -32,7 +32,7 @@ impl Handler for RequireUserAgent {
         let has_user_agent = !agent.is_empty() && agent != self.cdn_user_agent;
         let is_download = req.path().ends_with("download");
         if !has_user_agent && !is_download {
-            add_custom_metadata(req, "cause", "no user agent");
+            add_custom_metadata("cause", "no user agent");
             let body = format!(
                 include_str!("no_user_agent_message.txt"),
                 request_header(req, "x-request-id"),