diff --git a/CHANGELOG.md b/CHANGELOG.md index 74ebfa84..9ebb862c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,8 @@ ### Added +* feat(log): add opt-in structured logging for client construction and HTTP requests [#253] + ### Changed * feat(client): enable request pipelining for `AsyncClient` [#245] diff --git a/Cargo-minimal.lock b/Cargo-minimal.lock index 761a4b72..36c5c66c 100644 --- a/Cargo-minimal.lock +++ b/Cargo-minimal.lock @@ -264,9 +264,9 @@ dependencies = [ [[package]] name = "cfg-if" -version = "0.1.2" +version = "0.1.6" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d4c819a1287eb618df47cc647173c5c4c66ba19d888a6e50d605672aed3140de" +checksum = "082bb9b28e00d3c9d39cc03e64ce4cea0f1bb9b3fde493f0cbc008472d22bdf4" [[package]] name = "cfg-if" @@ -402,6 +402,7 @@ dependencies = [ "electrsd", "flate2", "hex-conservative 0.2.2", + "log", "mio 0.8.11", "openssl", "openssl-sys", @@ -411,6 +412,7 @@ dependencies = [ "tar", "tempfile", "tokio", + "tracing", ] [[package]] @@ -421,11 +423,11 @@ checksum = "6999dc1837253364c2ebb0704ba97994bd874e8f195d665c50b7548f6ea92764" [[package]] name = "filetime" -version = "0.2.13" +version = "0.2.8" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0c122a393ea57648015bf06fbd3d372378992e86b9ff5a7a497b076a28c79efe" +checksum = "1ff6d4dab0aa0c8e6346d46052e93b13a16cf847b54ed357087c35011048cc7d" dependencies = [ - "cfg-if 1.0.0", + "cfg-if 0.1.6", "libc", "redox_syscall 0.1.0", "winapi", @@ -547,11 +549,11 @@ dependencies = [ [[package]] name = "log" -version = "0.4.8" +version = "0.4.17" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "14b6052be84e6b71ab17edffc2eeabf5c2c3ae1fdb464aae35ac50c67a44e1f7" +checksum = "abb12e687cfb44aa40f41fc3978ef76448f9b6038cad6aef4259d3c095a2382e" dependencies = [ - "cfg-if 0.1.2", + "cfg-if 1.0.0", ] [[package]] @@ -1100,6 +1102,26 @@ dependencies = [ "tokio", ] +[[package]] +name = "tracing" +version = "0.1.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100" +dependencies = [ + "log", + "pin-project-lite", + "tracing-core", +] + +[[package]] +name = "tracing-core" +version = "0.1.36" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" +dependencies = [ + "once_cell", +] + [[package]] name = "unicode-ident" version = "1.0.0" diff --git a/Cargo-recent.lock b/Cargo-recent.lock index 24102f15..70717b65 100644 --- a/Cargo-recent.lock +++ b/Cargo-recent.lock @@ -339,6 +339,7 @@ dependencies = [ "electrsd", "flate2", "hex-conservative", + "log", "mio 0.8.11", "openssl", "openssl-sys", @@ -348,6 +349,7 @@ dependencies = [ "tar", "tempfile", "tokio", + "tracing", ] [[package]] @@ -1035,6 +1037,26 @@ dependencies = [ "tokio", ] +[[package]] +name = "tracing" +version = "0.1.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100" +dependencies = [ + "log", + "pin-project-lite", + "tracing-core", +] + +[[package]] +name = "tracing-core" +version = "0.1.36" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" +dependencies = [ + "once_cell", +] + [[package]] name = "unicode-ident" version = "1.0.24" diff --git a/Cargo.toml b/Cargo.toml index 69a23a2e..00e33cc4 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -26,8 +26,10 @@ hex = { version = "0.2.2", package = "hex-conservative" } serde = { version = "1.0.194", features = ["derive"] } serde_json = { version = "1.0.117", features = ["std"], default-features = false } tokio = { version = "1.44.2", features = ["time"], optional = true } # Async Client Transport +tracing = { version = "0.1.44", default-features = false, features = ["std", "log"], optional = true } [dev-dependencies] +log = "0.4.17" electrsd = { version = "0.41.0", default-features = false, features = ["legacy", "esplora_a33e97e1", "bitcoind_download", "bitcoind_29_0"] } tokio = { version = "1.44.2", features = ["full"] } # Transitive dependency pins: @@ -45,6 +47,7 @@ tempfile = { version = ">=3.4.0, <=3.15.0" } # blame: remove_dir_all@0.5.0 -> te [features] default = ["blocking", "blocking-https", "async", "async-https", "tokio"] +log = ["dep:tracing"] tokio = ["dep:tokio"] async = ["bitreq/async", "bitreq/proxy", "bitreq/json-using-serde", "tokio?/time"] @@ -95,6 +98,9 @@ exclude_features = [ # Run tests using these exact feature sets exact_features = [ ["async", "blocking"], + ["async", "log"], + ["blocking", "log"], + ["async", "blocking", "log"], ["async-https", "blocking-https", "tokio"], ["async-https-native", "blocking-https-native", "tokio"], ["async-https-rustls", "blocking-https-rustls", "tokio"], diff --git a/src/async.rs b/src/async.rs index 5c866520..86dfec6a 100644 --- a/src/async.rs +++ b/src/async.rs @@ -100,6 +100,16 @@ impl AsyncClient { /// Returns an [`Error`] if the HTTP client fails to build, /// or if any of the provided header names or values are invalid. pub fn from_builder(builder: Builder) -> Result { + log_debug!( + event = "client_build", + client = "async", + timeout = ?builder.timeout, + max_retries = builder.max_retries, + max_connections = builder.max_connections, + proxy_configured = builder.proxy.is_some(), + header_count = builder.headers.len(), + "building Esplora client" + ); Ok(AsyncClient { url: builder.base_url, proxy: builder.proxy, @@ -150,7 +160,7 @@ impl AsyncClient { Ok(request) } - /// Sends a GET request to `url`, retrying on retryable status codes + /// Sends a GET request to `path`, retrying on retryable status codes /// with exponential backoff until [`AsyncClient::max_retries`] is reached. async fn get_with_retry(&self, path: &str) -> Result { let mut delay = BASE_BACKOFF_MILLIS; @@ -159,8 +169,36 @@ impl AsyncClient { let request = self.build_request(Method::Get, path)?.with_pipelining(); loop { - match request.clone().send_async_with_client(&self.client).await? { + log_trace!( + event = "request", + client = "async", + method = "GET", + path, + attempt = attempts + 1, + "sending Esplora request" + ); + let response = request.clone().send_async_with_client(&self.client).await?; + log_trace!( + event = "response", + client = "async", + method = "GET", + path, + attempt = attempts + 1, + status = response.status_code, + "received Esplora response" + ); + match response { response if attempts < self.max_retries && is_retryable(&response) => { + log_debug!( + event = "retry", + client = "async", + method = "GET", + path, + attempt = attempts + 1, + status = response.status_code, + delay_ms = delay.as_millis(), + "retrying Esplora request" + ); S::sleep(delay).await; attempts += 1; delay *= 2; @@ -324,7 +362,24 @@ impl AsyncClient { request = request.with_param(key, value); } + log_trace!( + event = "request", + client = "async", + method = "POST", + path, + attempt = 1, + "sending Esplora request" + ); let response = request.send_async_with_client(&self.client).await?; + log_trace!( + event = "response", + client = "async", + method = "POST", + path, + attempt = 1, + status = response.status_code, + "received Esplora response" + ); if !is_success(&response) { let status = u16::try_from(response.status_code).map_err(Error::StatusCode)?; diff --git a/src/blocking.rs b/src/blocking.rs index 11e8091b..e4c22e3a 100644 --- a/src/blocking.rs +++ b/src/blocking.rs @@ -86,6 +86,15 @@ impl BlockingClient { /// This consumes the builder configuration and stores it on the client. /// No network request is made until a client method is called. pub fn from_builder(builder: Builder) -> Self { + log_debug!( + event = "client_build", + client = "blocking", + timeout = ?builder.timeout, + max_retries = builder.max_retries, + proxy_configured = builder.proxy.is_some(), + header_count = builder.headers.len(), + "building Esplora client" + ); Self { url: builder.base_url, proxy: builder.proxy, @@ -145,7 +154,24 @@ impl BlockingClient { request = request.with_param(key, value); } + log_trace!( + event = "request", + client = "blocking", + method = "POST", + path, + attempt = 1, + "sending Esplora request" + ); let response = request.send()?; + log_trace!( + event = "response", + client = "blocking", + method = "POST", + path, + attempt = 1, + status = response.status_code, + "received Esplora response" + ); if !is_success(&response) { let status = u16::try_from(response.status_code).map_err(Error::StatusCode)?; @@ -156,15 +182,44 @@ impl BlockingClient { Ok(response) } - /// Sends a GET request to `url`, retrying on retryable status codes + /// Sends a GET request to `path`, retrying on retryable status codes /// with exponential backoff until [`BlockingClient::max_retries`] is reached. - fn get_with_retry(&self, url: &str) -> Result { + fn get_with_retry(&self, path: &str) -> Result { let mut delay = BASE_BACKOFF_MILLIS; let mut attempts = 0; loop { - match self.build_request(Method::Get, url)?.send()? { + let request = self.build_request(Method::Get, path)?; + log_trace!( + event = "request", + client = "blocking", + method = "GET", + path, + attempt = attempts + 1, + "sending Esplora request" + ); + let response = request.send()?; + log_trace!( + event = "response", + client = "blocking", + method = "GET", + path, + attempt = attempts + 1, + status = response.status_code, + "received Esplora response" + ); + match response { resp if attempts < self.max_retries && is_retryable(&resp) => { + log_debug!( + event = "retry", + client = "blocking", + method = "GET", + path, + attempt = attempts + 1, + status = resp.status_code, + delay_ms = delay.as_millis(), + "retrying Esplora request" + ); thread::sleep(delay); attempts += 1; delay *= 2; diff --git a/src/lib.rs b/src/lib.rs index f1f8c008..a94c26bb 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -56,7 +56,8 @@ //! //! # Features //! -//! By default the crate enables all features. To select only the pieces you +//! By default the crate enables both clients, their default TLS backends, and Tokio. +//! Logging is opt-in. To select only the pieces you //! need, set `default-features = false` in `Cargo.toml` and list the desired //! features explicitly: //! @@ -83,8 +84,19 @@ //! * `async-https-rustls-probe` enables [`bitreq`], the async client with support for proxying and //! TLS (SSL) using `rustls` and probed system roots. //! * `tokio` enables the default async sleeper used by [`Builder::build_async`]. +//! * `log` enables structured [`tracing`] events. Disabled by default. +//! +//! # Logging +//! +//! The `log` feature emits `DEBUG` events for client construction and retries, +//! and `TRACE` events for HTTP requests and responses. +//! +//! The application must configure either a tracing subscriber or a `log` logger. +//! Headers, bodies, base URLs, and proxy values are omitted. Request paths are +//! included and may contain addresses or transaction IDs. //! //! [Esplora]: https://github.com/Blockstream/esplora/blob/master/API.md +//! [tracing]: https://docs.rs/tracing //! [`bitreq`]: https://docs.rs/bitreq #![allow(clippy::result_large_err)] #![warn(missing_docs)] @@ -98,6 +110,22 @@ use std::time::Duration; #[cfg(feature = "async")] pub use r#async::Sleeper; +#[cfg(any(feature = "blocking", feature = "async"))] +macro_rules! log_debug { + ($($arg:tt)*) => {{ + #[cfg(feature = "log")] + tracing::debug!($($arg)*); + }}; +} + +#[cfg(any(feature = "blocking", feature = "async"))] +macro_rules! log_trace { + ($($arg:tt)*) => {{ + #[cfg(feature = "log")] + tracing::trace!($($arg)*); + }}; +} + pub mod api; #[cfg(feature = "async")] pub mod r#async; diff --git a/tests/log_compat.rs b/tests/log_compat.rs new file mode 100644 index 00000000..da4931b5 --- /dev/null +++ b/tests/log_compat.rs @@ -0,0 +1,90 @@ +// SPDX-License-Identifier: MIT OR Apache-2.0 + +//! # Tests for `log` Compatibility +//! +//! A separate test executable isolates the process-global logger from tracing subscribers. +#![cfg(any(feature = "blocking", feature = "async"))] + +use std::sync::Mutex; + +struct Logger(Mutex>); + +impl log::Log for Logger { + fn enabled(&self, metadata: &log::Metadata<'_>) -> bool { + metadata.target().starts_with("esplora_client::") + } + + fn log(&self, record: &log::Record<'_>) { + if self.enabled(record.metadata()) { + self.0 + .lock() + .unwrap() + .push((record.level(), record.args().to_string())); + } + } + + fn flush(&self) {} +} + +static LOGGER: Logger = Logger(Mutex::new(Vec::new())); + +#[cfg(feature = "async")] +struct Sleeper; + +#[cfg(feature = "async")] +impl esplora_client::Sleeper for Sleeper { + type Sleep = tokio::time::Sleep; + + fn sleep(duration: std::time::Duration) -> Self::Sleep { + tokio::time::sleep(duration) + } +} + +#[tokio::test] +async fn test_logger_receives_events_only_when_feature_is_enabled() { + log::set_logger(&LOGGER).unwrap(); + log::set_max_level(log::LevelFilter::Trace); + // Fail deterministically during send, without making a network connection. + let builder = esplora_client::Builder::new("http://invalid\0host") + .header("Authorization", "header-secret"); + #[cfg(feature = "blocking")] + { + assert!(builder.clone().build_blocking().get_height().is_err()); + assert_records(); + } + #[cfg(feature = "async")] + { + assert!(builder + .build_async_with_sleeper::() + .unwrap() + .get_height() + .await + .is_err()); + assert_records(); + } +} + +fn assert_records() { + let mut records = LOGGER.0.lock().unwrap(); + if cfg!(feature = "log") { + assert_eq!( + records.len(), + 2, + "expected construction and request records: {records:?}" + ); + assert_eq!(records[0].0, log::Level::Debug); + assert!(records[0].1.contains("client_build")); + assert_eq!(records[1].0, log::Level::Trace); + assert!(records[1].1.contains("/blocks/tip/height")); + for (_, message) in records.iter() { + assert!(!message.contains("header-secret")); + assert!(!message.contains("invalid")); + } + } else { + assert!( + records.is_empty(), + "disabled logging emitted records: {records:?}" + ); + } + records.clear(); +} diff --git a/tests/logging.rs b/tests/logging.rs new file mode 100644 index 00000000..8afda5dc --- /dev/null +++ b/tests/logging.rs @@ -0,0 +1,371 @@ +// SPDX-License-Identifier: MIT OR Apache-2.0 + +//! # Tests for Structured Logging + +#![cfg(all(feature = "log", any(feature = "blocking", feature = "async")))] + +use std::collections::BTreeMap; +use std::fmt; +use std::sync::{Arc, Mutex}; +use std::time::Duration; + +use tokio::io::{AsyncBufReadExt, AsyncReadExt, AsyncWriteExt, BufReader}; +use tokio::net::TcpListener; +use tokio::time::timeout; + +use bitcoin::{absolute, transaction, Transaction, Txid}; +use esplora_client::{Builder, Error}; +use tracing::field::{Field, Visit}; +use tracing::instrument::WithSubscriber; +use tracing::span::{Attributes, Id, Record}; +use tracing::{Event, Level, Metadata, Subscriber}; + +#[derive(Debug)] +struct LoggedEvent { + level: Level, + fields: BTreeMap, +} + +impl Visit for LoggedEvent { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + self.fields + .insert(field.name().into(), format!("{value:?}")); + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.fields.insert(field.name().into(), value.into()); + } +} + +// Scoped subscribers keep tests independent even when the harness runs them in parallel. +#[derive(Clone, Default)] +struct Capture(Arc>>); + +impl Subscriber for Capture { + fn enabled(&self, metadata: &Metadata<'_>) -> bool { + metadata.target().starts_with("esplora_client::") + } + + fn new_span(&self, _: &Attributes<'_>) -> Id { + Id::from_u64(1) + } + + fn record(&self, _: &Id, _: &Record<'_>) {} + fn record_follows_from(&self, _: &Id, _: &Id) {} + fn enter(&self, _: &Id) {} + fn exit(&self, _: &Id) {} + + fn event(&self, event: &Event<'_>) { + let mut logged = LoggedEvent { + level: *event.metadata().level(), + fields: BTreeMap::new(), + }; + event.record(&mut logged); + self.0.lock().unwrap().push(logged); + } +} + +fn private_builder() -> Builder { + Builder::new("http://url-user:url-secret@localhost/base-secret") + .proxy("http://proxy-user:proxy-secret@localhost:9050") + .header("Authorization", "header-secret") + .timeout(Duration::from_secs(3)) + .max_retries(2) +} + +fn assert_build(capture: &Capture, client: &str) { + let events = capture.0.lock().unwrap(); + assert_eq!(events.len(), 1, "client construction must emit one event"); + let event = &events[0]; + assert_eq!(event.level, Level::DEBUG); + assert_eq!(event.fields["event"], "client_build"); + assert_eq!(event.fields["client"], client); + assert_eq!(event.fields["max_retries"], "2"); + assert_eq!(event.fields["timeout"], "Some(3s)"); + assert_eq!(event.fields["proxy_configured"], "true"); + assert_eq!(event.fields["header_count"], "1"); + let output = format!("{events:?}"); + for secret in [ + "url-user", + "url-secret", + "base-secret", + "proxy-user", + "proxy-secret", + "header-secret", + ] { + assert!(!output.contains(secret), "leaked {secret}"); + } +} + +#[cfg(feature = "blocking")] +#[test] +fn test_blocking_construction_logs_safe_configuration() { + let capture = Capture::default(); + tracing::subscriber::with_default(capture.clone(), || { + private_builder().build_blocking(); + }); + assert_build(&capture, "blocking"); +} + +#[cfg(feature = "async")] +struct TestSleeper; + +#[cfg(feature = "async")] +impl esplora_client::Sleeper for TestSleeper { + type Sleep = tokio::time::Sleep; + + fn sleep(duration: Duration) -> Self::Sleep { + tokio::time::sleep(duration) + } +} + +#[cfg(feature = "async")] +#[test] +fn test_async_construction_logs_safe_configuration() { + let capture = Capture::default(); + tracing::subscriber::with_default(capture.clone(), || { + private_builder() + .max_connections(4) + .build_async_with_sleeper::() + .unwrap(); + }); + assert_build(&capture, "async"); + assert_eq!(capture.0.lock().unwrap()[0].fields["max_connections"], "4"); +} + +#[derive(Clone, Copy)] +enum Mode { + #[cfg(feature = "blocking")] + Blocking, + #[cfg(feature = "async")] + Async, +} + +fn modes() -> Vec { + vec![ + #[cfg(feature = "blocking")] + Mode::Blocking, + #[cfg(feature = "async")] + Mode::Async, + ] +} + +impl Mode { + fn name(self) -> &'static str { + match self { + #[cfg(feature = "blocking")] + Self::Blocking => "blocking", + #[cfg(feature = "async")] + Self::Async => "async", + } + } + + fn build(self, url: &str, retries: usize) -> Client { + let builder = Builder::new(url) + .timeout(Duration::from_secs(3)) + .header("Authorization", "header-secret") + .max_retries(retries); + match self { + #[cfg(feature = "blocking")] + Self::Blocking => Client::Blocking(builder.build_blocking()), + #[cfg(feature = "async")] + Self::Async => Client::Async(builder.build_async_with_sleeper().unwrap()), + } + } +} + +enum Client { + #[cfg(feature = "blocking")] + Blocking(esplora_client::BlockingClient), + #[cfg(feature = "async")] + Async(esplora_client::AsyncClient), +} + +impl Client { + async fn height(&self) -> Result { + match self { + #[cfg(feature = "blocking")] + Self::Blocking(client) => client.get_height(), + #[cfg(feature = "async")] + Self::Async(client) => client.get_height().await, + } + } + + async fn broadcast(&self, tx: &Transaction) -> Result { + match self { + #[cfg(feature = "blocking")] + Self::Blocking(client) => client.broadcast(tx), + #[cfg(feature = "async")] + Self::Async(client) => client.broadcast(tx).await, + } + } +} + +// Real HTTP responses exercise both transports. Bound the entire exchange so missing +// requests or incomplete headers/bodies fail instead of hanging the test process. +type RequestBodies = Vec>; + +async fn server(responses: &[(u16, &str)]) -> (String, tokio::task::JoinHandle) { + let listener = TcpListener::bind("127.0.0.1:0").await.unwrap(); + let url = format!("http://{}", listener.local_addr().unwrap()); + let responses: Vec<_> = responses + .iter() + .map(|(code, body)| (*code, body.to_string())) + .collect(); + let handle = tokio::spawn(async move { + timeout(Duration::from_secs(5), async move { + let mut requests = Vec::new(); + for (status, body) in responses { + let (mut stream, _) = listener.accept().await.unwrap(); + let mut reader = BufReader::new(&mut stream); + let mut request_line = String::new(); + reader.read_line(&mut request_line).await.unwrap(); + let mut content_length = 0; + loop { + let mut line = String::new(); + assert_ne!(reader.read_line(&mut line).await.unwrap(), 0); + if line == "\r\n" { + break; + } + if let Some((name, value)) = line.split_once(':') { + if name.eq_ignore_ascii_case("content-length") { + content_length = value.trim().parse().unwrap(); + } + } + } + let mut request_body = vec![0; content_length]; + reader.read_exact(&mut request_body).await.unwrap(); + requests.push(request_body); + let response = format!( + "HTTP/1.1 {status} Test\r\nContent-Length: {}\r\nConnection: close\r\n\r\n{body}", + body.len() + ); + stream.write_all(response.as_bytes()).await.unwrap(); + } + requests + }).await.expect("client did not complete expected HTTP exchanges") + }); + (url, handle) +} + +fn assert_lifecycle( + capture: &Capture, + mode: Mode, + method: &str, + path: &str, + expected: &[(&str, usize, Option, Option)], +) { + let captured = capture.0.lock().unwrap(); + let events: Vec<_> = captured + .iter() + .filter(|event| event.fields["event"] != "client_build") + .collect(); + assert_eq!(events.len(), expected.len(), "{captured:?}"); + for (event, (kind, attempt, status, delay)) in events.iter().zip(expected) { + assert_eq!(event.fields["event"], *kind); + assert_eq!(event.fields["client"], mode.name()); + assert_eq!(event.fields["method"], method); + assert_eq!(event.fields["path"], path); + assert_eq!(event.fields["attempt"], attempt.to_string()); + assert_eq!( + event.fields.get("status"), + status.map(|value| value.to_string()).as_ref() + ); + assert_eq!( + event.fields.get("delay_ms"), + delay.map(|value| value.to_string()).as_ref() + ); + assert_eq!( + event.level, + if *kind == "retry" { + Level::DEBUG + } else { + Level::TRACE + } + ); + } + let output = format!("{captured:?}"); + assert!(!output.contains("header-secret")); + assert!(!output.contains("response-secret")); + assert!(!output.contains("base-path-secret")); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn test_get_logs_request_response_and_retry() { + for mode in modes() { + let (url, server) = server(&[(503, "response-secret"), (200, "42")]).await; + let capture = Capture::default(); + assert_eq!( + async { + mode.build(&format!("{url}/base-path-secret"), 1) + .height() + .await + } + .with_subscriber(capture.clone()) + .await + .unwrap(), + 42 + ); + assert_eq!(server.await.unwrap().len(), 2); + assert_lifecycle( + &capture, + mode, + "GET", + "/blocks/tip/height", + &[ + ("request", 1, None, None), + ("response", 1, Some(503), None), + ("retry", 1, Some(503), Some(256)), + ("request", 2, None, None), + ("response", 2, Some(200), None), + ], + ); + } +} + +fn transaction() -> Transaction { + Transaction { + version: transaction::Version::TWO, + lock_time: absolute::LockTime::ZERO, + input: vec![], + output: vec![], + } +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn test_post_logs_metadata_without_bodies_or_retries() { + let txid = "0000000000000000000000000000000000000000000000000000000000000000"; + let tx = transaction(); + for mode in modes() { + for (status, body) in [(200, txid), (503, "response-secret")] { + let (url, server) = server(&[(status, body)]).await; + let capture = Capture::default(); + let result = async { mode.build(&url, 2).broadcast(&tx).await } + .with_subscriber(capture.clone()) + .await; + if status == 200 { + assert_eq!(result.unwrap().to_string(), txid); + } else { + assert!(matches!( + result, + Err(Error::HttpResponse { status: 503, .. }) + )); + } + let requests = server.await.unwrap(); + assert_eq!(requests.len(), 1); + let body = String::from_utf8(requests[0].clone()).unwrap(); + assert!(!body.is_empty()); + assert!(!format!("{:?}", capture.0.lock().unwrap()).contains(&body)); + assert_lifecycle( + &capture, + mode, + "POST", + "/tx", + &[ + ("request", 1, None, None), + ("response", 1, Some(status), None), + ], + ); + } + } +}