Skip to content

Commit

Permalink
Add request ID to meta request failures and add tests
Browse files Browse the repository at this point in the history
A side effect of awslabs#669 was
that there's now no way to get request IDs for failed requests at the
default logging settings, as only DEBUG-level messages include the
request IDs. This change adds request IDs to the meta request failure
message when available, so that these WARN-level messages still include
request IDs.

I also added some new infrastructure to test metrics and log messages.
For metrics, we build a new `metrics::Recorder` that collects all the
metrics and can then be searched to find them. For log messages, we
build a `tracing_subscriber::Layer` that collects all tracing events
emitted while enabled. In both cases, the new objects aren't thread
safe, as both `Recorder`s and `Layer`s are global state. So these tests
need to continue to use `rusty_fork` to split into a new process per
test.

Signed-off-by: James Bornholt <[email protected]>
  • Loading branch information
jamesbornholt committed Feb 28, 2024
1 parent 9326a48 commit c271be0
Show file tree
Hide file tree
Showing 6 changed files with 395 additions and 11 deletions.
1 change: 1 addition & 0 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

1 change: 1 addition & 0 deletions mountpoint-s3-client/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@ rand = { version = "0.8.5", optional = true }
rand_chacha = { version = "0.3.1", optional = true }

[dev-dependencies]
mountpoint-s3-crt-sys = { path = "../mountpoint-s3-crt-sys" }
anyhow = { version = "1.0.64", features = ["backtrace"] }
aws-config = "1.1.4"
aws-credential-types = "1.1.4"
Expand Down
28 changes: 18 additions & 10 deletions mountpoint-s3-client/src/s3_crt_client.rs
Original file line number Diff line number Diff line change
Expand Up @@ -464,12 +464,12 @@ impl S3CrtClientInner {
let range = metrics.response_headers().and_then(|headers| extract_range_header(&headers));

let message = if request_failure {
"CRT request failed"
"S3 request failed"
} else {
"CRT request finished"
"S3 request finished"
};
debug!(%request_type, ?crt_error, http_status, ?range, ?duration, ?ttfb, %request_id, "{}", message);
trace!(detailed_metrics=?metrics, "CRT request completed");
trace!(detailed_metrics=?metrics, "S3 request completed");

let op = span_telemetry.metadata().map(|m| m.name()).unwrap_or("unknown");
if let Some(ttfb) = ttfb {
Expand Down Expand Up @@ -535,11 +535,20 @@ impl S3CrtClientInner {
Ok(t)
}
Err(maybe_err) => {
// Try to parse request header out of the failure. We can't just use the
// telemetry callback because there might be multiple requests per meta
// request, but these headers are known to be from the failed request.
let request_id = match &request_result.error_response_headers {
Some(headers) => headers.get("x-amz-request-id").map(|s| s.value().to_string_lossy().to_string()).ok(),
None => None,
};
let request_id = request_id.unwrap_or_else(|| "<unknown>".into());

if let Some(error) = &maybe_err {
event!(log_level, ?duration, ?error, "meta request failed");
event!(log_level, ?duration, %request_id, ?error, "meta request failed");
debug!("failed meta request result: {:?}", request_result);
} else {
event!(log_level, ?duration, ?request_result, "meta request failed");
event!(log_level, ?duration, %request_id, ?request_result, "meta request failed");
}

// If it's not a real HTTP status, encode the CRT error in the metric instead
Expand Down Expand Up @@ -1237,8 +1246,8 @@ mod tests {

#[test]
fn parse_no_signing_credential_error() {
// 6146 is crt error code for AWS_AUTH_SIGNING_NO_CREDENTIALS
let result = make_crt_error_result(0, 6146.into());
let error_code = mountpoint_s3_crt_sys::aws_auth_errors::AWS_AUTH_SIGNING_NO_CREDENTIALS as i32;
let result = make_crt_error_result(0, error_code.into());
let result = try_parse_generic_error(&result);
let Some(S3RequestError::NoSigningCredentials) = result else {
panic!("wrong result, got: {:?}", result);
Expand All @@ -1247,9 +1256,8 @@ mod tests {

#[test]
fn parse_test_other_crt_error() {
// 6144 is crt error code for AWS_AUTH_SIGNING_UNSUPPORTED_ALGORITHM, which is another signing error,
// but not no signing credential error
let error_code = 6144;
// A signing error that isn't "no signing credentials"
let error_code = mountpoint_s3_crt_sys::aws_auth_errors::AWS_AUTH_SIGNING_UNSUPPORTED_ALGORITHM as i32;
let result = make_crt_error_result(0, error_code.into());
let result = try_parse_generic_error(&result);
let Some(S3RequestError::CrtError(error)) = result else {
Expand Down
11 changes: 10 additions & 1 deletion mountpoint-s3-client/tests/common/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -15,12 +15,21 @@ use mountpoint_s3_crt::common::rust_log_adapter::RustLogAdapter;
use rand::rngs::OsRng;
use rand::RngCore;
use std::ops::Range;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::util::SubscriberInitExt as _;
use tracing_subscriber::{EnvFilter, Layer};

pub mod tracing_test;

/// Enable tracing and CRT logging when running unit tests.
#[ctor::ctor]
fn init_tracing_subscriber() {
let _ = RustLogAdapter::try_init();
let _ = tracing_subscriber::fmt::try_init();

let subscriber = tracing_subscriber::registry()
.with(tracing_subscriber::fmt::layer().with_filter(EnvFilter::from_default_env()))
.with(self::tracing_test::TracingTestLayer::get());
let _ = subscriber.try_init();
}

pub enum AccessPointType {
Expand Down
84 changes: 84 additions & 0 deletions mountpoint-s3-client/tests/common/tracing_test.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,84 @@
use std::sync::atomic::{AtomicBool, Ordering};
use std::sync::{Arc, Mutex};

use once_cell::sync::Lazy;
use tracing::{Event, Level, Subscriber};
use tracing_subscriber::field::VisitOutput;
use tracing_subscriber::fmt::format::{DefaultVisitor, Writer};
use tracing_subscriber::layer::Context;
use tracing_subscriber::Layer;

static TRACING_TEST_LAYER: Lazy<TracingTestLayer> = Lazy::new(TracingTestLayer::new);

/// This is a singleton [tracing::Layer] that can be used to write tests for log events.
///
/// Use it like this:
/// ```rust
/// let _guard = TracingTestLayer::enable();
/// // ... do work that emits tracing events ...
/// drop(_guard);
/// let events = TracingTestLayer::take_events();
/// // events is a list of all events emitted
/// ```
///
/// THIS IS NOT THREAD SAFE! tracing doesn't give us a good way to separate threads, as tracing
/// subscribers are global state. You almost certainly want to use [rusty_fork] to write tests using
/// this layer.
#[derive(Debug, Default, Clone)]
pub struct TracingTestLayer {
inner: Arc<Inner>,
}

#[derive(Debug, Default)]
struct Inner {
events: Mutex<Vec<(Level, String)>>,
enabled: AtomicBool,
}

impl TracingTestLayer {
fn new() -> Self {
Self {
inner: Arc::new(Inner {
events: Mutex::new(Vec::new()),
enabled: AtomicBool::new(false),
}),
}
}

/// Get a handle to the singleton layer
pub fn get() -> Self {
TRACING_TEST_LAYER.clone()
}

/// Start collecting tracing events, and stop collecting them when the returned guard drops.
#[must_use = "returns a guard that disables tracing when dropped"]
pub fn enable() -> TracingTestLayerEnableGuard {
TRACING_TEST_LAYER.inner.enabled.store(true, Ordering::SeqCst);
TracingTestLayerEnableGuard {}
}

/// Take all the collected events
pub fn take_events() -> Vec<(Level, String)> {
TRACING_TEST_LAYER.inner.events.lock().unwrap().drain(..).collect()
}
}

impl<S: Subscriber> Layer<S> for TracingTestLayer {
fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
if self.inner.enabled.load(Ordering::SeqCst) {
let mut msg = String::new();
let writer = Writer::new(&mut msg);
let visitor = DefaultVisitor::new(writer, true);
visitor.visit(event).unwrap();
self.inner.events.lock().unwrap().push((*event.metadata().level(), msg));
}
}
}

pub struct TracingTestLayerEnableGuard;

impl Drop for TracingTestLayerEnableGuard {
fn drop(&mut self) {
TRACING_TEST_LAYER.inner.enabled.store(false, Ordering::SeqCst);
}
}
Loading

0 comments on commit c271be0

Please sign in to comment.