From 394072bbd9f000f2f542e63a7b3b4a41158dcd39 Mon Sep 17 00:00:00 2001 From: Conrad Ludgate Date: Thu, 10 Aug 2023 11:13:15 +0100 Subject: [PATCH 1/4] proxy: http logging to 11 --- Cargo.lock | 1 + Cargo.toml | 1 + proxy/Cargo.toml | 1 + proxy/src/console/provider/neon.rs | 5 ++- proxy/src/http.rs | 50 ++++++++++++++++++++++++++++-- proxy/src/logging.rs | 3 ++ 6 files changed, 58 insertions(+), 3 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index c18bddfbcb76..ac3c99f81592 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3104,6 +3104,7 @@ dependencies = [ "tokio-rustls 0.23.4", "tokio-util", "tracing", + "tracing-log", "tracing-opentelemetry", "tracing-subscriber", "tracing-utils", diff --git a/Cargo.toml b/Cargo.toml index a0acc061fbc1..b71259fd5d05 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -130,6 +130,7 @@ toml = "0.7" toml_edit = "0.19" tonic = {version = "0.9", features = ["tls", "tls-roots"]} tracing = "0.1" +tracing-log = "0.1" tracing-error = "0.2.0" tracing-opentelemetry = "0.19.0" tracing-subscriber = { version = "0.3", default_features = false, features = ["smallvec", "fmt", "tracing-log", "std", "env-filter"] } diff --git a/proxy/Cargo.toml b/proxy/Cargo.toml index 438dd62315be..e122e5bb9ded 100644 --- a/proxy/Cargo.toml +++ b/proxy/Cargo.toml @@ -54,6 +54,7 @@ tls-listener.workspace = true tokio-postgres.workspace = true tokio-rustls.workspace = true tokio = { workspace = true, features = ["signal"] } +tracing-log.workspace = true tracing-opentelemetry.workspace = true tracing-subscriber.workspace = true tracing-utils.workspace = true diff --git a/proxy/src/console/provider/neon.rs b/proxy/src/console/provider/neon.rs index 22e766b5f13b..a6ef06c11af5 100644 --- a/proxy/src/console/provider/neon.rs +++ b/proxy/src/console/provider/neon.rs @@ -8,8 +8,9 @@ use super::{ use crate::{auth::ClientCredentials, compute, http, scram}; use async_trait::async_trait; use futures::TryFutureExt; +use tokio::time::Instant; use tokio_postgres::config::SslMode; -use tracing::{error, info, info_span, warn, Instrument}; +use tracing::{error, info, info_span, trace, warn, Instrument}; #[derive(Clone)] pub struct Api { @@ -88,7 +89,9 @@ impl Api { .build()?; info!(url = request.url().as_str(), "sending http request"); + let start = Instant::now(); let response = self.endpoint.execute(request).await?; + trace!(duration = ?start.elapsed(), "received http response"); let body = parse_body::(response).await?; // Unfortunately, ownership won't let us use `Option::ok_or` here. diff --git a/proxy/src/http.rs b/proxy/src/http.rs index e2812403806d..149d508bbbfe 100644 --- a/proxy/src/http.rs +++ b/proxy/src/http.rs @@ -7,11 +7,14 @@ pub mod server; pub mod sql_over_http; pub mod websocket; -use std::time::Duration; +use std::{sync::Arc, time::Duration}; +use futures::FutureExt; pub use reqwest::{Request, Response, StatusCode}; pub use reqwest_middleware::{ClientWithMiddleware, Error}; pub use reqwest_retry::{policies::ExponentialBackoff, RetryTransientMiddleware}; +use tokio::time::Instant; +use tracing::trace; use crate::url::ApiUrl; use reqwest_middleware::RequestBuilder; @@ -20,13 +23,21 @@ use reqwest_middleware::RequestBuilder; /// because it takes care of observability (OpenTelemetry). /// We deliberately don't want to replace this with a public static. pub fn new_client() -> ClientWithMiddleware { - reqwest_middleware::ClientBuilder::new(reqwest::Client::new()) + let client = reqwest::ClientBuilder::new() + .dns_resolver(Arc::new(GaiResolver::default())) + .connection_verbose(true) + .build() + .expect("Failed to create http client"); + + reqwest_middleware::ClientBuilder::new(client) .with(reqwest_tracing::TracingMiddleware::default()) .build() } pub fn new_client_with_timeout(default_timout: Duration) -> ClientWithMiddleware { let timeout_client = reqwest::ClientBuilder::new() + .dns_resolver(Arc::new(GaiResolver::default())) + .connection_verbose(true) .timeout(default_timout) .build() .expect("Failed to create http client with timeout"); @@ -39,6 +50,10 @@ pub fn new_client_with_timeout(default_timout: Duration) -> ClientWithMiddleware // As per docs, "This middleware always errors when given requests with streaming bodies". // That's all right because we only use this client to send `serde_json::RawValue`, which // is not a stream. + // + // ex-maintainer note: + // this limitatioin can be fixed if streaming is necessary. + // retries will still not be performed, but it wont error immediately .with(RetryTransientMiddleware::new_with_policy(retry_policy)) .build() } @@ -81,6 +96,37 @@ impl Endpoint { } } +/// https://docs.rs/reqwest/0.11.18/src/reqwest/dns/gai.rs.html +use hyper::{ + client::connect::dns::{GaiResolver as HyperGaiResolver, Name}, + service::Service, +}; +use reqwest::dns::{Addrs, Resolve, Resolving}; +#[derive(Debug)] +pub struct GaiResolver(HyperGaiResolver); + +impl Default for GaiResolver { + fn default() -> Self { + Self(HyperGaiResolver::new()) + } +} + +impl Resolve for GaiResolver { + fn resolve(&self, name: Name) -> Resolving { + let this = &mut self.0.clone(); + let start = Instant::now(); + Box::pin( + Service::::call(this, name.clone()).map(move |result| { + let resolve_duration = start.elapsed(); + trace!(duration = ?resolve_duration, addr = %name, "resolve host complete"); + result + .map(|addrs| -> Addrs { Box::new(addrs) }) + .map_err(|err| -> Box { Box::new(err) }) + }), + ) + } +} + #[cfg(test)] mod tests { use super::*; diff --git a/proxy/src/logging.rs b/proxy/src/logging.rs index 3405b8cbc672..b24ac57bcec5 100644 --- a/proxy/src/logging.rs +++ b/proxy/src/logging.rs @@ -1,3 +1,4 @@ +use tracing_log::LogTracer; use tracing_opentelemetry::OpenTelemetryLayer; use tracing_subscriber::{ filter::{EnvFilter, LevelFilter}, @@ -17,6 +18,8 @@ pub async fn init() -> anyhow::Result { .with_default_directive(LevelFilter::INFO.into()) .from_env_lossy(); + LogTracer::init()?; + let fmt_layer = tracing_subscriber::fmt::layer() .with_ansi(false) .with_writer(std::io::stderr) From 7e1da389064f0977ede83c687b48f74d42594c4e Mon Sep 17 00:00:00 2001 From: Conrad Ludgate Date: Thu, 10 Aug 2023 11:24:44 +0100 Subject: [PATCH 2/4] hakari --- Cargo.lock | 1 + proxy/src/http.rs | 2 +- workspace_hack/Cargo.toml | 1 + 3 files changed, 3 insertions(+), 1 deletion(-) diff --git a/Cargo.lock b/Cargo.lock index ac3c99f81592..888741b23de4 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5356,6 +5356,7 @@ dependencies = [ "tower", "tracing", "tracing-core", + "tracing-log", "tracing-subscriber", "url", ] diff --git a/proxy/src/http.rs b/proxy/src/http.rs index 149d508bbbfe..755137807bc4 100644 --- a/proxy/src/http.rs +++ b/proxy/src/http.rs @@ -52,7 +52,7 @@ pub fn new_client_with_timeout(default_timout: Duration) -> ClientWithMiddleware // is not a stream. // // ex-maintainer note: - // this limitatioin can be fixed if streaming is necessary. + // this limitation can be fixed if streaming is necessary. // retries will still not be performed, but it wont error immediately .with(RetryTransientMiddleware::new_with_policy(retry_policy)) .build() diff --git a/workspace_hack/Cargo.toml b/workspace_hack/Cargo.toml index d79c7a4104fc..397029f2f10b 100644 --- a/workspace_hack/Cargo.toml +++ b/workspace_hack/Cargo.toml @@ -54,6 +54,7 @@ toml_edit = { version = "0.19", features = ["serde"] } tower = { version = "0.4", features = ["balance", "buffer", "limit", "retry", "timeout", "util"] } tracing = { version = "0.1", features = ["log"] } tracing-core = { version = "0.1" } +tracing-log = { version = "0.1" } tracing-subscriber = { version = "0.3", default-features = false, features = ["env-filter", "fmt", "json", "smallvec", "tracing-log"] } url = { version = "2", features = ["serde"] } From 7013948951331f495fdec4568558a698dee9c96e Mon Sep 17 00:00:00 2001 From: Conrad Ludgate Date: Thu, 10 Aug 2023 12:01:03 +0100 Subject: [PATCH 3/4] tracing-log is enabled implicitly --- Cargo.lock | 2 -- Cargo.toml | 1 - proxy/Cargo.toml | 1 - proxy/src/logging.rs | 3 --- workspace_hack/Cargo.toml | 1 - 5 files changed, 8 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 888741b23de4..c18bddfbcb76 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3104,7 +3104,6 @@ dependencies = [ "tokio-rustls 0.23.4", "tokio-util", "tracing", - "tracing-log", "tracing-opentelemetry", "tracing-subscriber", "tracing-utils", @@ -5356,7 +5355,6 @@ dependencies = [ "tower", "tracing", "tracing-core", - "tracing-log", "tracing-subscriber", "url", ] diff --git a/Cargo.toml b/Cargo.toml index b71259fd5d05..a0acc061fbc1 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -130,7 +130,6 @@ toml = "0.7" toml_edit = "0.19" tonic = {version = "0.9", features = ["tls", "tls-roots"]} tracing = "0.1" -tracing-log = "0.1" tracing-error = "0.2.0" tracing-opentelemetry = "0.19.0" tracing-subscriber = { version = "0.3", default_features = false, features = ["smallvec", "fmt", "tracing-log", "std", "env-filter"] } diff --git a/proxy/Cargo.toml b/proxy/Cargo.toml index e122e5bb9ded..438dd62315be 100644 --- a/proxy/Cargo.toml +++ b/proxy/Cargo.toml @@ -54,7 +54,6 @@ tls-listener.workspace = true tokio-postgres.workspace = true tokio-rustls.workspace = true tokio = { workspace = true, features = ["signal"] } -tracing-log.workspace = true tracing-opentelemetry.workspace = true tracing-subscriber.workspace = true tracing-utils.workspace = true diff --git a/proxy/src/logging.rs b/proxy/src/logging.rs index b24ac57bcec5..3405b8cbc672 100644 --- a/proxy/src/logging.rs +++ b/proxy/src/logging.rs @@ -1,4 +1,3 @@ -use tracing_log::LogTracer; use tracing_opentelemetry::OpenTelemetryLayer; use tracing_subscriber::{ filter::{EnvFilter, LevelFilter}, @@ -18,8 +17,6 @@ pub async fn init() -> anyhow::Result { .with_default_directive(LevelFilter::INFO.into()) .from_env_lossy(); - LogTracer::init()?; - let fmt_layer = tracing_subscriber::fmt::layer() .with_ansi(false) .with_writer(std::io::stderr) diff --git a/workspace_hack/Cargo.toml b/workspace_hack/Cargo.toml index 397029f2f10b..d79c7a4104fc 100644 --- a/workspace_hack/Cargo.toml +++ b/workspace_hack/Cargo.toml @@ -54,7 +54,6 @@ toml_edit = { version = "0.19", features = ["serde"] } tower = { version = "0.4", features = ["balance", "buffer", "limit", "retry", "timeout", "util"] } tracing = { version = "0.1", features = ["log"] } tracing-core = { version = "0.1" } -tracing-log = { version = "0.1" } tracing-subscriber = { version = "0.3", default-features = false, features = ["env-filter", "fmt", "json", "smallvec", "tracing-log"] } url = { version = "2", features = ["serde"] } From f4c797a24674e7350d15715fa7e7020cb87547be Mon Sep 17 00:00:00 2001 From: Conrad Ludgate Date: Thu, 10 Aug 2023 16:59:25 +0100 Subject: [PATCH 4/4] info log --- proxy/src/console/provider/neon.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/proxy/src/console/provider/neon.rs b/proxy/src/console/provider/neon.rs index a6ef06c11af5..3f4cee6e3483 100644 --- a/proxy/src/console/provider/neon.rs +++ b/proxy/src/console/provider/neon.rs @@ -10,7 +10,7 @@ use async_trait::async_trait; use futures::TryFutureExt; use tokio::time::Instant; use tokio_postgres::config::SslMode; -use tracing::{error, info, info_span, trace, warn, Instrument}; +use tracing::{error, info, info_span, warn, Instrument}; #[derive(Clone)] pub struct Api { @@ -48,7 +48,9 @@ impl Api { .build()?; info!(url = request.url().as_str(), "sending http request"); + let start = Instant::now(); let response = self.endpoint.execute(request).await?; + info!(duration = ?start.elapsed(), "received http response"); let body = match parse_body::(response).await { Ok(body) => body, // Error 404 is special: it's ok not to have a secret. @@ -91,7 +93,7 @@ impl Api { info!(url = request.url().as_str(), "sending http request"); let start = Instant::now(); let response = self.endpoint.execute(request).await?; - trace!(duration = ?start.elapsed(), "received http response"); + info!(duration = ?start.elapsed(), "received http response"); let body = parse_body::(response).await?; // Unfortunately, ownership won't let us use `Option::ok_or` here.