Improve logging configuration

Cargo.toml

@@ -17,6 +17,7 @@ publish = false
 [dependencies]
 anyhow = "1.0.79"
 async-stream = "0.3.5"
+async-trait = "0.1.77"
 aws-config = { version = "1.1.4", features = ["behavior-version-latest"] }
 aws-sdk-s3 = "1.14.0"
 aws-smithy-runtime-api = "1.1.4"
@@ -32,16 +33,19 @@ itertools = "0.12.1"
 moka = { version = "0.12.5", features = ["future"] }
 percent-encoding = "2.3.1"
 reqwest = { version = "0.11.24", default-features = false, features = ["json", "rustls-tls-native-roots"] }
+reqwest-middleware = "0.2.4"
 serde = { version = "1.0.196", features = ["derive"] }
 serde_json = { version = "1.0.113", features = ["preserve_order"] }
 serde_yaml = "0.9.31"
 smartstring = "1.0.1"
+task-local-extensions = "0.1.4"
 tera = { version = "1.19.1", default-features = false }
 thiserror = "1.0.56"
 time = { version = "0.3.34", features = ["formatting", "macros", "parsing", "serde"] }
 tokio = { version = "1.36.0", features = ["macros", "net", "rt-multi-thread"] }
 tower = "0.4.13"
 tower-http = { version = "0.5.1", features = ["set-header", "trace"] }
+tracing = "0.1.40"
 tracing-subscriber = "0.3.18"
 url = { version = "2.5.0", features = ["serde"] }
 xml-rs = "0.8.19"

src/dandi/mod.rs

@@ -5,7 +5,7 @@
 pub(crate) use self::types::*;
 pub(crate) use self::version_id::*;
 use crate::consts::S3CLIENT_CACHE_SIZE;
-use crate::httputil::{get_json, new_client, urljoin_slashed, BuildClientError, HttpError};
+use crate::httputil::{urljoin_slashed, BuildClientError, Client, HttpError};
 use crate::paths::{ParsePureDirPathError, PureDirPath, PurePath};
 use crate::s3::{
     BucketSpec, GetBucketRegionError, PrefixedS3Client, S3Client, S3Error, S3Location,
@@ -21,14 +21,14 @@
 
 #[derive(Clone, Debug)]
 pub(crate) struct DandiClient {
-    inner: reqwest::Client,
+    inner: Client,
     api_url: Url,
     s3clients: Cache<BucketSpec, Arc<S3Client>>,
 }
 
 impl DandiClient {
     pub(crate) fn new(api_url: Url) -> Result<Self, BuildClientError> {
-        let inner = new_client()?;
+        let inner = Client::new()?;
         let s3clients = CacheBuilder::new(S3CLIENT_CACHE_SIZE)
             .name("s3clients")
             .build();
@@ -48,7 +48,7 @@
     }
 
     async fn get<T: DeserializeOwned>(&self, url: Url) -> Result<T, DandiError> {
-        get_json(&self.inner, url).await.map_err(Into::into)
+        self.inner.get_json(url).await.map_err(Into::into)
     }
 
     fn paginate<T: DeserializeOwned + 'static>(
@@ -58,7 +58,7 @@
         try_stream! {
             let mut url = Some(url);
             while let Some(u) = url {
-                let page = get_json::<Page<T>>(&self.inner, u).await?;
+                let page = self.inner.get_json::<Page<T>>(u).await?;
                 for r in page.results {
                     yield r;
                 }

src/httputil.rs

@@ -1,53 +1,97 @@
 use crate::consts::USER_AGENT;
-use reqwest::{ClientBuilder, StatusCode};
+use reqwest::{Method, Request, Response, StatusCode};
+use reqwest_middleware::{Middleware, Next};
 use serde::de::DeserializeOwned;
 use thiserror::Error;
+use tracing::Instrument;
 use url::Url;
 
-pub(crate) fn new_client() -> Result<reqwest::Client, BuildClientError> {
-    ClientBuilder::new()
-        .user_agent(USER_AGENT)
-        .build()
-        .map_err(Into::into)
-}
+#[derive(Debug, Clone)]
+pub(crate) struct Client(reqwest_middleware::ClientWithMiddleware);
+
+impl Client {
+    pub(crate) fn new() -> Result<Client, BuildClientError> {
+        let client = reqwest_middleware::ClientBuilder::new(
+            reqwest::ClientBuilder::new()
+                .user_agent(USER_AGENT)
+                .build()?,
+        )
+        .with(SimpleReqwestLogger)
+        .build();
+        Ok(Client(client))
+    }
 
-#[derive(Debug, Error)]
-#[error("failed to initialize HTTP client")]
-pub(crate) struct BuildClientError(#[from] reqwest::Error);
+    pub(crate) async fn request(&self, method: Method, url: Url) -> Result<Response, HttpError> {
+        let r = self
+            .0
+            .request(method, url.clone())
+            .send()
+            .await
+            .map_err(|source| HttpError::Send {
+                url: url.clone(),
+                source,
+            })?;
+        if r.status() == StatusCode::NOT_FOUND {
+            return Err(HttpError::NotFound { url });
+        }
+        r.error_for_status()
+            .map_err(|source| HttpError::Status { url, source })
+    }
 
-async fn get_response(client: &reqwest::Client, url: Url) -> Result<reqwest::Response, HttpError> {
-    let r = client
-        .get(url.clone())
-        .send()
-        .await
-        .map_err(|source| HttpError::Send {
-            url: url.clone(),
-            source,
-        })?;
-    if r.status() == StatusCode::NOT_FOUND {
-        return Err(HttpError::NotFound { url: url.clone() });
+    pub(crate) async fn head(&self, url: Url) -> Result<Response, HttpError> {
+        self.request(Method::HEAD, url).await
+    }
+
+    pub(crate) async fn get(&self, url: Url) -> Result<Response, HttpError> {
+        self.request(Method::GET, url).await
+    }
+
+    pub(crate) async fn get_json<T: DeserializeOwned>(&self, url: Url) -> Result<T, HttpError> {
+        self.get(url.clone())
+            .await?
+            .json::<T>()
+            .await
+            .map_err(move |source| HttpError::Deserialize { url, source })
     }
-    r.error_for_status().map_err(|source| HttpError::Status {
-        url: url.clone(),
-        source,
-    })
 }
 
-pub(crate) async fn get_json<T: DeserializeOwned>(
-    client: &reqwest::Client,
-    url: Url,
-) -> Result<T, HttpError> {
-    get_response(client, url.clone())
-        .await?
-        .json::<T>()
+#[derive(Copy, Clone, Debug, Eq, PartialEq)]
+struct SimpleReqwestLogger;
+
+#[async_trait::async_trait]
+impl Middleware for SimpleReqwestLogger {
+    async fn handle(
+        &self,
+        req: Request,
+        extensions: &mut task_local_extensions::Extensions,
+        next: Next<'_>,
+    ) -> reqwest_middleware::Result<Response> {
+        let span = tracing::debug_span!("http-request", url = %req.url(), method = %req.method());
+        async move {
+            tracing::debug!("Making HTTP request");
+            let r = next.run(req, extensions).await;
+            match r {
+                Ok(ref resp) => tracing::debug!(status = %resp.status(), "Response received"),
+                Err(ref e) => tracing::debug!(error = ?e, "Failed to receive response"),
+            }
+            r
+        }
+        .instrument(span)
         .await
-        .map_err(move |source| HttpError::Deserialize { url, source })
+    }
 }
 
+#[derive(Debug, Error)]
+#[error("failed to initialize HTTP client")]
+pub(crate) struct BuildClientError(#[from] reqwest::Error);
+
 #[derive(Debug, Error)]
 pub(crate) enum HttpError {
     #[error("failed to make request to {url}")]
-    Send { url: Url, source: reqwest::Error },
+    Send {
+        url: Url,
+        source: reqwest_middleware::Error,
+    },
     #[error("no such resource: {url}")]
     NotFound { url: Url },
     #[error("request to {url} returned error")]

src/main.rs

@@ -23,11 +23,13 @@
     Router,
 };
 use clap::Parser;
+use std::io::{stderr, IsTerminal};
 use std::net::IpAddr;
 use std::sync::Arc;
 use tower::service_fn;
 use tower_http::{set_header::response::SetResponseHeaderLayer, trace::TraceLayer};
-use tracing_subscriber::filter::LevelFilter;
+use tracing::Level;
+use tracing_subscriber::{filter::Targets, prelude::*};
 
 static STYLESHEET: &str = include_str!("dav/static/styles.css");
 
@@ -57,8 +59,20 @@
 #[tokio::main]
 async fn main() -> anyhow::Result<()> {
     let args = Arguments::parse();
-    tracing_subscriber::fmt()
-        .with_max_level(LevelFilter::TRACE)
+    tracing_subscriber::registry()
+        .with(
+            tracing_subscriber::fmt::layer()
+                .with_ansi(stderr().is_terminal())
+                .with_writer(stderr),
+        )
+        .with(
+            Targets::new()
+                .with_target(env!("CARGO_CRATE_NAME"), Level::TRACE)
+                .with_target("aws_config", Level::DEBUG)
+                .with_target("reqwest", Level::TRACE)
+                .with_target("tower_http", Level::TRACE)
+                .with_default(Level::INFO),
+        )
         .init();
     let dandi = DandiClient::new(args.api_url)?;
     let zarrman = ZarrManClient::new()?;

src/s3.rs

@@ -1,11 +1,10 @@
-use super::consts::USER_AGENT;
-use super::paths::{ParsePureDirPathError, ParsePurePathError, PureDirPath, PurePath};
+use crate::httputil::{self, BuildClientError, HttpError};
+use crate::paths::{ParsePureDirPathError, ParsePurePathError, PureDirPath, PurePath};
 use async_stream::try_stream;
 use aws_sdk_s3::{operation::list_objects_v2::ListObjectsV2Error, types::CommonPrefix, Client};
 use aws_smithy_runtime_api::client::{orchestrator::HttpResponse, result::SdkError};
 use aws_smithy_types_convert::date_time::DateTimeExt;
 use futures_util::{Stream, TryStreamExt};
-use reqwest::ClientBuilder;
 use smartstring::alias::CompactString;
 use std::cmp::Ordering;
 use std::sync::Arc;
@@ -492,18 +491,15 @@
 // The AWS SDK currently cannot be used for this:
 // <https://github.com/awslabs/aws-sdk-rust/issues/1052>
 pub(crate) async fn get_bucket_region(bucket: &str) -> Result<String, GetBucketRegionError> {
-    let client = ClientBuilder::new()
-        .user_agent(USER_AGENT)
-        .https_only(true)
-        .build()
-        .map_err(GetBucketRegionError::BuildClient)?;
-    let r = client
-        .head(format!("https://{bucket}.s3.amazonaws.com"))
-        .send()
-        .await
-        .map_err(GetBucketRegionError::Send)?
-        .error_for_status()
-        .map_err(GetBucketRegionError::Status)?;
+    let url_str = format!("https://{bucket}.s3.amazonaws.com");
+    let url = url_str
+        .parse::<Url>()
+        .map_err(|source| GetBucketRegionError::BadUrl {
+            url: url_str,
+            source,
+        })?;
+    let client = httputil::Client::new()?;
+    let r = client.head(url).await?;
     match r.headers().get("x-amz-bucket-region").map(|hv| hv.to_str()) {
         Some(Ok(region)) => Ok(region.to_owned()),
         Some(Err(e)) => Err(GetBucketRegionError::BadHeader(e)),
@@ -513,12 +509,15 @@
 
 #[derive(Debug, Error)]
 pub(crate) enum GetBucketRegionError {
-    #[error("failed to initialize HTTP client")]
-    BuildClient(#[source] reqwest::Error),
-    #[error("failed to make S3 request")]
-    Send(#[source] reqwest::Error),
-    #[error("S3 request returned error")]
-    Status(#[source] reqwest::Error),
+    #[error(transparent)]
+    BuildClient(#[from] BuildClientError),
+    #[error(transparent)]
+    Http(#[from] HttpError),
+    #[error("URL constructed for bucket is invalid: {url:?}")]
+    BadUrl {
+        url: String,
+        source: url::ParseError,
+    },
     #[error("S3 response lacked x-amz-bucket-region header")]
     NoHeader,
     #[error("S3 response had undecodable x-amz-bucket-region header")]