From dd01db25d86e8a8dfad3d07e4dfa733582c093db Mon Sep 17 00:00:00 2001 From: lym953 <10097700+lym953@users.noreply.github.com> Date: Fri, 16 Oct 2026 12:31:37 -0400 Subject: [PATCH 1/3] [SLES-3059] feat(logs): keep HTTP library log lines out of Datadog The extension sends its own stdout to Datadog as logs. The HTTP libraries (h2, hyper, reqwest, rustls) log each request, including the requests that send those logs, so their lines must stay out of the upload. Otherwise each flush logs lines for the next flush to send. - The formatter starts each line from those targets with `{"target":"",` and appends the event's other fields as `name=value`, so that h2 frame lines show the frame. - The Lambda logs processor drops extension records that start that way. The lines still reach CloudWatch. - The logger is installed with `init()`, which also forwards records from the `log` crate to it. - The default-off filter for these targets is built from the same list. - The logger README says that these lines appear only in CloudWatch. Co-Authored-By: Claude Opus 5.5 --- bottlecap/Cargo.lock | 1 + bottlecap/Cargo.toml | 1 + bottlecap/src/bin/bottlecap/main.rs | 11 +- bottlecap/src/logger/README.md | 2 + bottlecap/src/logger/mod.rs | 153 ++++++++++++++++++++++++- bottlecap/src/logs/lambda/processor.rs | 26 +++++ 6 files changed, 186 insertions(+), 8 deletions(-) diff --git a/bottlecap/Cargo.lock b/bottlecap/Cargo.lock index 0784bc9e1..86ac6b45d 100644 --- a/bottlecap/Cargo.lock +++ b/bottlecap/Cargo.lock @@ -568,6 +568,7 @@ dependencies = [ "tower-http", "tracing", "tracing-core", + "tracing-log", "tracing-subscriber", "ustr", "zstd", diff --git a/bottlecap/Cargo.toml b/bottlecap/Cargo.toml index 68cf42869..d75f5e6f3 100644 --- a/bottlecap/Cargo.toml +++ b/bottlecap/Cargo.toml @@ -39,6 +39,7 @@ tokio = { version = "1.47", default-features = false, features = ["macros", "rt- tokio-util = { version = "0.7", default-features = false } tracing = { version = "0.1", default-features = false } tracing-core = { version = "0.1", default-features = false } +tracing-log = { version = "0.2", default-features = false, features = ["std"] } tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "fmt", "env-filter", "tracing-log"] } hmac = { version = "0.12", default-features = false } sha2 = { version = "0.10", default-features = false } diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs index 7d986f976..08e406dc4 100644 --- a/bottlecap/src/bin/bottlecap/main.rs +++ b/bottlecap/src/bin/bottlecap/main.rs @@ -108,6 +108,7 @@ use tokio::time::Instant; use tokio::{sync::Mutex as TokioMutex, sync::mpsc::Sender}; use tokio_util::sync::CancellationToken; use tracing::{debug, error, warn}; +use tracing_subscriber::util::SubscriberInitExt; use ustr::Ustr; fn resolve_dsm_service( @@ -234,9 +235,14 @@ fn enable_logging_subsystem() { ) .unwrap_or(LogLevel::Info); + let http_libraries_off: Vec = logger::HTTP_LIBRARY_TARGETS + .iter() + .map(|target| format!("{target}=off")) + .collect(); let (env_filter, invalid_entries) = build_env_filter( &format!( - "h2=off,hyper=off,reqwest=off,rustls=off,datadog-trace-mini-agent=off,{log_level:?}" + "{},datadog-trace-mini-agent=off,{log_level:?}", + http_libraries_off.join(",") ), &std::env::var(LEVEL_BY_TARGET_ENV_VAR).unwrap_or_default(), ) @@ -252,7 +258,8 @@ fn enable_logging_subsystem() { .without_time() .event_format(logger::Formatter) .finish(); - tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed"); + // `init` also forwards records from crates that log with the `log` crate to this subscriber. + subscriber.init(); if !invalid_entries.is_empty() { warn!("Ignoring invalid {LEVEL_BY_TARGET_ENV_VAR} entries: {invalid_entries:?}"); diff --git a/bottlecap/src/logger/README.md b/bottlecap/src/logger/README.md index 0c86b5aae..72325638b 100644 --- a/bottlecap/src/logger/README.md +++ b/bottlecap/src/logger/README.md @@ -14,3 +14,5 @@ A level is `off`, `error`, `warn`, `info`, `debug` or `trace`. For example, if ` An entry matches each target that starts with its text. For an entry that is not valid, the extension logs a warning that names the entry, and skips it. Use the targets that `mod.rs` defines, such as `cold_start_duration`. Other targets are module paths and crate names, which change when the code moves. + +The logs of `h2`, `hyper`, `reqwest` and `rustls` appear only in CloudWatch. The extension does not send them to Datadog, because these libraries log each request, including the requests that send the extension's logs. They are off by default. For example, `hyper_util=debug,h2=debug` shows each TCP connect and each HTTP/2 frame of the uploads to Datadog. diff --git a/bottlecap/src/logger/mod.rs b/bottlecap/src/logger/mod.rs index 6419f4fdf..19c3a528c 100644 --- a/bottlecap/src/logger/mod.rs +++ b/bottlecap/src/logger/mod.rs @@ -1,5 +1,6 @@ -use std::fmt; +use std::fmt::{self, Write as _}; use tracing_core::{Event, Subscriber}; +use tracing_log::NormalizeEvent; use tracing_subscriber::fmt::{ FmtContext, FormattedFields, format::{self, FormatEvent, FormatFields}, @@ -15,6 +16,42 @@ pub mod cold_start; /// Tracing target for the duration of each cold start step. pub const COLD_START_DURATION: &str = "cold_start_duration"; +/// HTTP libraries that log each request, including the requests that send the extension's own +/// logs to Datadog. The extension does not send their lines to Datadog, so that a flush cannot +/// log lines for the next flush to send. +pub const HTTP_LIBRARY_TARGETS: &[&str] = &["h2", "hyper", "reqwest", "rustls"]; + +/// Starts each line that the formatter writes for an [`HTTP_LIBRARY_TARGETS`] target. +const HTTP_LIBRARY_LINE_PREFIX: &str = "{\"target\":\""; + +fn is_http_library_target(target: &str) -> bool { + HTTP_LIBRARY_TARGETS + .iter() + .any(|library| target.starts_with(library)) +} + +/// Returns true if `record`, an `extension` record from the Telemetry API, is a line that the +/// formatter wrote for an [`HTTP_LIBRARY_TARGETS`] target. The message check keeps the lines of +/// other extensions. +#[must_use] +pub fn is_http_library_record(record: &serde_json::Value) -> bool { + const MESSAGE_PREFIX: &str = "DD_EXTENSION | "; + match record { + serde_json::Value::String(line) => { + line.starts_with(HTTP_LIBRARY_LINE_PREFIX) + && line.contains(&format!(",\"message\":\"{MESSAGE_PREFIX}")) + } + serde_json::Value::Object(obj) => { + obj.contains_key("target") + && obj + .get("message") + .and_then(serde_json::Value::as_str) + .is_some_and(|message| message.starts_with(MESSAGE_PREFIX)) + } + _ => false, + } +} + /// Writes `s` to `w` with the 6 mandatory JSON string escape sequences applied. /// Handles: `"`, `\`, `\n`, `\r`, `\t`, and U+0000–U+001F control characters. fn write_json_escaped(w: &mut impl fmt::Write, s: &str) -> fmt::Result { @@ -36,25 +73,40 @@ fn write_json_escaped(w: &mut impl fmt::Write, s: &str) -> fmt::Result { pub struct Formatter; /// Visitor that captures the message and the `f64` fields of a tracing event, so that Datadog -/// parses those fields as numbers. It drops fields of other types. To write another type, add -/// its `record_*` method. +/// parses those fields as numbers. It keeps the other fields as `name=value` text, which only +/// HTTP library lines write. To write another type, add its `record_*` method. #[derive(Default)] struct FieldVisitor { message: String, /// The `f64` fields, in the order of the event. fields: Vec<(&'static str, f64)>, + /// The other fields as ` name=value` text. h2, for example, logs each frame in a `frame` field. + other_fields: String, +} + +impl FieldVisitor { + fn record_other(&mut self, field: &tracing::field::Field, value: fmt::Arguments<'_>) { + // `log.*` fields carry the target and location of a record from the `log` crate. + if !field.name().starts_with("log.") { + let _ = write!(self.other_fields, " {}={value}", field.name()); + } + } } impl tracing::field::Visit for FieldVisitor { fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn fmt::Debug) { if field.name() == "message" { self.message = format!("{value:?}"); + } else { + self.record_other(field, format_args!("{value:?}")); } } fn record_str(&mut self, field: &tracing::field::Field, value: &str) { if field.name() == "message" { self.message = value.to_string(); + } else { + self.record_other(field, format_args!("{value}")); } } @@ -99,7 +151,9 @@ where mut writer: format::Writer<'_>, event: &Event<'_>, ) -> fmt::Result { - let metadata = event.metadata(); + // A record from the `log` crate arrives with the target `log`, and its own target in a field. + let normalized = event.normalized_metadata(); + let metadata = normalized.as_ref().unwrap_or_else(|| event.metadata()); let level = metadata.level(); let mut visitor = FieldVisitor::default(); @@ -122,12 +176,27 @@ where } } - let message = format!("DD_EXTENSION | {level} | {span_prefix}{}", visitor.message); + let is_http_library = is_http_library_target(metadata.target()); + let other_fields = if is_http_library { + visitor.other_fields.as_str() + } else { + "" + }; + let message = format!( + "DD_EXTENSION | {level} | {span_prefix}{}{other_fields}", + visitor.message + ); // Setting specifically `status` as opposed to `level` since AWS // filters out logs by the `level` field. This allows our logs to // appear in CWL regardless of the log level. - write!(writer, "{{\"status\":\"{level}\",\"message\":\"")?; + writer.write_char('{')?; + if is_http_library { + writer.write_str("\"target\":\"")?; + write_json_escaped(&mut writer, metadata.target())?; + writer.write_str("\",")?; + } + write!(writer, "\"status\":\"{level}\",\"message\":\"")?; write_json_escaped(&mut writer, &message)?; writer.write_char('"')?; for (key, value) in fields_to_json(&visitor.fields) { @@ -376,4 +445,76 @@ mod tests { assert!(parsed.get("count").is_none()); assert!(parsed.get("name").is_none()); } + + #[test] + fn test_formatter_starts_http_library_line_with_target() { + let output = capture_log(|| { + tracing::debug!( + target: "hyper_util::client::legacy::connect::http", + "connecting to 34.149.115.168:443" + ); + }); + + assert!(output.starts_with( + r#"{"target":"hyper_util::client::legacy::connect::http","status":"DEBUG","# + )); + let parsed: serde_json::Value = serde_json::from_str(output.trim()).unwrap(); + assert!(is_http_library_record(&serde_json::Value::String( + output.trim().to_string() + ))); + assert!(is_http_library_record(&parsed)); + } + + #[test] + fn test_formatter_uses_target_of_log_crate_record() { + let output = capture_log(|| { + tracing_log::format_trace( + &log::Record::builder() + .target("rustls::client::hs") + .level(log::Level::Debug) + .args(format_args!("Not resuming any session")) + .build(), + ) + .unwrap(); + }); + + assert!(output.starts_with(r#"{"target":"rustls::client::hs","status":"DEBUG","#)); + assert!(output.contains(r#"DD_EXTENSION | DEBUG | Not resuming any session""#)); + } + + #[test] + fn test_formatter_writes_other_fields_only_for_http_library_lines() { + let output = capture_log(|| { + tracing::debug!(target: "h2::codec::framed_write", frame = ?("Headers", 1), "send"); + tracing::debug!(target: "bottlecap::traces", attempt = 1_u64, "Attempting request"); + }); + let lines: Vec<&str> = output.lines().collect(); + + assert!(lines[0].contains(r#"DD_EXTENSION | DEBUG | send frame=(\"Headers\", 1)""#)); + assert!(lines[1].contains(r#"DD_EXTENSION | DEBUG | Attempting request""#)); + } + + #[test] + fn test_formatter_writes_no_target_for_extension_line() { + let output = capture_log(|| { + tracing::debug!(target: "bottlecap::traces", "Flushing 1 traces"); + }); + + assert!(output.starts_with(r#"{"status":"DEBUG","#)); + assert!(!is_http_library_record(&serde_json::Value::String( + output.trim().to_string() + ))); + } + + #[test] + fn test_is_http_library_record_keeps_other_extension_lines() { + let other_extension = serde_json::json!({"target": "app", "message": "started"}); + assert!(!is_http_library_record(&other_extension)); + assert!(!is_http_library_record(&serde_json::Value::String( + r#"{"target":"app","message":"started"}"#.to_string() + ))); + assert!(!is_http_library_record(&serde_json::Value::String( + "plain text line".to_string() + ))); + } } diff --git a/bottlecap/src/logs/lambda/processor.rs b/bottlecap/src/logs/lambda/processor.rs index 4e9928782..96da34dc5 100644 --- a/bottlecap/src/logs/lambda/processor.rs +++ b/bottlecap/src/logs/lambda/processor.rs @@ -12,6 +12,7 @@ use crate::event_bus::Event; use crate::extension::telemetry::events::ReportMetrics; use crate::extension::telemetry::events::{Status, TelemetryEvent, TelemetryRecord}; use crate::lifecycle::invocation::context::Context as InvocationContext; +use crate::logger; use crate::logs::aggregator_service::AggregatorHandle; use crate::logs::processor::{Processor, Rule}; use crate::tags::provider; @@ -242,6 +243,9 @@ impl LambdaProcessor { Err("Unable to parse log".into()) } TelemetryRecord::Extension(v) => { + if logger::is_http_library_record(&v) { + return Err("HTTP library log, kept out of Datadog".into()); + } let message = match v { serde_json::Value::Object(obj) => Some(serde_json::to_string(&obj).unwrap_or_default()), serde_json::Value::String(s) => Some(s), @@ -2361,6 +2365,28 @@ mod tests { assert_eq!(intake_log.message.status, "debug"); } + #[tokio::test] + async fn test_http_library_log_is_not_sent() { + let config = Arc::new(config::Config::default()); + let tags_provider = Arc::new(provider::Provider::new( + Arc::clone(&config), + LAMBDA_RUNTIME_SLUG.to_string(), + &HashMap::from([("function_arn".to_string(), "test-arn".to_string())]), + )); + let (tx, _rx) = tokio::sync::mpsc::channel(2); + let mut processor = + LambdaProcessor::new(tags_provider, Arc::clone(&config), tx.clone(), true); + + let event = TelemetryEvent { + time: Utc.with_ymd_and_hms(2023, 1, 7, 3, 23, 47).unwrap(), + record: TelemetryRecord::Extension(Value::String( + r#"{"target":"hyper_util::client::legacy::connect::http","status":"DEBUG","message":"DD_EXTENSION | DEBUG | connecting to 34.149.115.168:443"}"# + .to_string(), + )), + }; + assert!(processor.make_log(event).await.is_err()); + } + #[tokio::test] async fn test_get_intake_log_non_string_level_defaults_to_info() { let config = Arc::new(config::Config { From f6a740b83b979279766c95e18526ebbdbbd15629 Mon Sep 17 00:00:00 2001 From: lym953 <10097700+lym953@users.noreply.github.com> Date: Fri, 16 Oct 2026 14:47:56 -0400 Subject: [PATCH 2/3] [SLES-3059] docs: say flush, not upload, in the logger README Co-Authored-By: Claude Opus 5.5 --- bottlecap/src/logger/README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bottlecap/src/logger/README.md b/bottlecap/src/logger/README.md index 72325638b..26a563e41 100644 --- a/bottlecap/src/logger/README.md +++ b/bottlecap/src/logger/README.md @@ -15,4 +15,4 @@ An entry matches each target that starts with its text. For an entry that is not Use the targets that `mod.rs` defines, such as `cold_start_duration`. Other targets are module paths and crate names, which change when the code moves. -The logs of `h2`, `hyper`, `reqwest` and `rustls` appear only in CloudWatch. The extension does not send them to Datadog, because these libraries log each request, including the requests that send the extension's logs. They are off by default. For example, `hyper_util=debug,h2=debug` shows each TCP connect and each HTTP/2 frame of the uploads to Datadog. +The logs of `h2`, `hyper`, `reqwest` and `rustls` appear only in CloudWatch. The extension does not send them to Datadog, because these libraries log each request, including the requests that send the extension's logs. They are off by default. For example, `hyper_util=debug,h2=debug` shows each TCP connect and each HTTP/2 frame of the flushes to Datadog. From b0ed4d755345ff2d991309b6b85888a6f79b21e0 Mon Sep 17 00:00:00 2001 From: lym953 <10097700+lym953@users.noreply.github.com> Date: Fri, 16 Oct 2026 14:51:03 -0400 Subject: [PATCH 3/3] [SLES-3059] docs: say CloudWatch Logs in the logger README Co-Authored-By: Claude Opus 5.5 --- bottlecap/src/logger/README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bottlecap/src/logger/README.md b/bottlecap/src/logger/README.md index 26a563e41..e08e0084c 100644 --- a/bottlecap/src/logger/README.md +++ b/bottlecap/src/logger/README.md @@ -15,4 +15,4 @@ An entry matches each target that starts with its text. For an entry that is not Use the targets that `mod.rs` defines, such as `cold_start_duration`. Other targets are module paths and crate names, which change when the code moves. -The logs of `h2`, `hyper`, `reqwest` and `rustls` appear only in CloudWatch. The extension does not send them to Datadog, because these libraries log each request, including the requests that send the extension's logs. They are off by default. For example, `hyper_util=debug,h2=debug` shows each TCP connect and each HTTP/2 frame of the flushes to Datadog. +The logs of `h2`, `hyper`, `reqwest` and `rustls` appear only in CloudWatch Logs. The extension does not send them to Datadog, because these libraries log each request, including the requests that send the extension's logs. They are off by default. For example, `hyper_util=debug,h2=debug` shows each TCP connect and each HTTP/2 frame of the flushes to Datadog.