From 91679a99b6a86dfc0286132261cdefb39f922f92 Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Wed, 7 Oct 2026 12:44:14 -0400
Subject: [PATCH 01/11] [SVLS-9883] Log the duration of each cold start step

Add debug logs under the "cold_start_duration" tracing target for each
non-trivial step before the extension is ready, and move the existing
"ready in" total under the same target.

Steps were chosen from five cold starts of a probe build that timed every
step. Steps that took under 0.1 ms in all runs were left out, except the
two that do expensive work only when a feature is on: resolving
additional endpoint secrets and creating the AppSec processor.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/bin/bottlecap/main.rs | 36 +++++++++++++++++++++++++++--
 1 file changed, 34 insertions(+), 2 deletions(-)

diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs
index 9623e5411..c201d4050 100644
--- a/bottlecap/src/bin/bottlecap/main.rs
+++ b/bottlecap/src/bin/bottlecap/main.rs
@@ -120,8 +120,11 @@ async fn main() -> anyhow::Result<()> {
     let start_time = Instant::now();
     init_ustr();
     enable_logging_subsystem();
+    log_cold_start_step("Enabling logging", start_time);
+    let step_start = Instant::now();
     let aws_config = AwsConfig::from_env(start_time);
     log_fips_status(&aws_config.region);
+    log_cold_start_step("Loading AWS config", step_start);
     let version_without_next = EXTENSION_VERSION.split('-').next().unwrap_or("NA");
     debug!("Starting Datadog Extension v{version_without_next}");
 
@@ -135,32 +138,41 @@ async fn main() -> anyhow::Result<()> {
         debug!("DD_DEBUG_WAIT_FOR_ATTACH: Continuing execution...");
     }
 
+    let step_start = Instant::now();
     prepare_client_provider()?;
     let client = create_reqwest_client_builder()
         .map_err(|e| anyhow::anyhow!("Failed to create client builder: {e:?}"))?
         .no_proxy()
         .build()
         .map_err(|e| anyhow::anyhow!("Failed to create client: {e:?}"))?;
+    log_cold_start_step("Creating the Extensions API client", step_start);
 
     let cloned_client = client.clone();
     let runtime_api = aws_config.runtime_api.clone();
     let managed_instance_mode = aws_config.is_managed_instance_mode();
     let response = tokio::task::spawn(async move {
-        extension::register(
+        let step_start = Instant::now();
+        let response = extension::register(
             &cloned_client,
             &runtime_api,
             extension::EXTENSION_NAME,
             managed_instance_mode,
         )
-        .await
+        .await;
+        log_cold_start_step("Registering the extension", step_start);
+        response
     });
     // First load the AWS configuration
     let lambda_directory: String =
         env::var("LAMBDA_TASK_ROOT").unwrap_or_else(|_| "/var/task".to_string());
     let aws_config = Arc::new(aws_config);
 
+    let step_start = Instant::now();
     let mut lambda_config = config::get_config(Path::new(&lambda_directory));
+    log_cold_start_step("Loading config", step_start);
+    let step_start = Instant::now();
     resolve_additional_endpoints_secrets(&mut lambda_config, &aws_config).await;
+    log_cold_start_step("Resolving additional endpoint secrets", step_start);
     let config = Arc::new(lambda_config);
 
     // Build one shared reqwest::Client for metrics, logs, trace proxy flushing, and calls to
@@ -169,10 +181,12 @@ async fn main() -> anyhow::Result<()> {
     let shared_client = bottlecap::http::get_client(&config);
     let api_key_factory = create_api_key_factory(&config, &aws_config, &shared_client);
 
+    let step_start = Instant::now();
     let r = response
         .await
         .map_err(|e| anyhow::anyhow!("Failed to join task: {e:?}"))?
         .map_err(|e| anyhow::anyhow!("Failed to register extension: {e:?}"))?;
+    log_cold_start_step("Waiting for extension registration", step_start);
 
     match extension_loop_active(
         Arc::clone(&aws_config),
@@ -204,6 +218,17 @@ fn init_ustr() {
     });
 }
 
+/// Tracing target for the duration of each cold start step.
+const COLD_START_DURATION: &str = "cold_start_duration";
+
+fn log_cold_start_step(step: &str, step_start: Instant) {
+    debug!(
+        target: COLD_START_DURATION,
+        "{step} took {:.3}ms",
+        step_start.elapsed().as_secs_f64() * 1000.0
+    );
+}
+
 fn enable_logging_subsystem() {
     let log_level = LogLevel::from_str(
         std::env::var("DD_LOG_LEVEL")
@@ -334,6 +359,7 @@ async fn extension_loop_active(
         &shared_client,
     );
 
+    let step_start = Instant::now();
     let (metrics_flushers, metrics_aggregator_handle, dogstatsd_cancel_token) = start_dogstatsd(
         tags_provider.clone(),
         Arc::clone(&api_key_factory),
@@ -341,6 +367,7 @@ async fn extension_loop_active(
         &shared_client,
     )
     .await;
+    log_cold_start_step("Starting DogStatsD", step_start);
 
     let propagator = Arc::new(DatadogCompositePropagator::new(Arc::clone(config)));
 
@@ -406,6 +433,7 @@ async fn extension_loop_active(
     });
 
     // AppSec processor (if enabled)
+    let step_start = Instant::now();
     let appsec_processor = match AppSecProcessor::new(config) {
         Ok(p) => Some(Arc::new(TokioMutex::new(p))),
         Err(AppSecFeatureDisabled) => None,
@@ -416,6 +444,7 @@ async fn extension_loop_active(
             None
         }
     };
+    log_cold_start_step("Creating the AppSec processor", step_start);
 
     let (
         trace_agent_channel,
@@ -454,6 +483,7 @@ async fn extension_loop_active(
         }
     });
 
+    let step_start = Instant::now();
     let telemetry_listener_cancel_token = setup_telemetry_client(
         client,
         &r.extension_id,
@@ -464,6 +494,7 @@ async fn extension_loop_active(
         aws_config.is_managed_instance_mode(),
     )
     .await?;
+    log_cold_start_step("Starting the telemetry listener", step_start);
 
     let otlp_cancel_token = start_otlp_agent(
         config,
@@ -480,6 +511,7 @@ async fn extension_loop_active(
     let mut flush_control = FlushControl::new(flush_strategy, config.flush_timeout);
 
     debug!(
+        target: COLD_START_DURATION,
         "Datadog Next-Gen Extension ready in {:}ms",
         start_time.elapsed().as_millis().to_string()
     );

From acf98dd2f55e8538466b229e70b8d8e7d165ff34 Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Wed, 7 Oct 2026 12:59:11 -0400
Subject: [PATCH 02/11] [SVLS-9883] Share duration logging across targets with
 a macro

Replace the cold-start-only helper with a log_duration! macro in the
library crate, so that later duration targets (trace flush, for example)
reuse it from any module. A function cannot take the target, because
tracing requires it to be a constant at each call site.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/bin/bottlecap/main.rs | 54 +++++++++++++++++------------
 bottlecap/src/logger.rs             | 17 +++++++++
 2 files changed, 49 insertions(+), 22 deletions(-)

diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs
index c201d4050..7aca77a3f 100644
--- a/bottlecap/src/bin/bottlecap/main.rs
+++ b/bottlecap/src/bin/bottlecap/main.rs
@@ -44,7 +44,8 @@ use bottlecap::{
         invocation::processor_service::{InvocationProcessorHandle, InvocationProcessorService},
         listener::Listener as LifecycleListener,
     },
-    logger,
+    log_duration,
+    logger::{self, COLD_START_DURATION},
     logs::{
         agent::LogsAgent,
         aggregator_service::{
@@ -120,11 +121,11 @@ async fn main() -> anyhow::Result<()> {
     let start_time = Instant::now();
     init_ustr();
     enable_logging_subsystem();
-    log_cold_start_step("Enabling logging", start_time);
+    log_duration!(COLD_START_DURATION, "Enabling logging", start_time);
     let step_start = Instant::now();
     let aws_config = AwsConfig::from_env(start_time);
     log_fips_status(&aws_config.region);
-    log_cold_start_step("Loading AWS config", step_start);
+    log_duration!(COLD_START_DURATION, "Loading AWS config", step_start);
     let version_without_next = EXTENSION_VERSION.split('-').next().unwrap_or("NA");
     debug!("Starting Datadog Extension v{version_without_next}");
 
@@ -145,7 +146,11 @@ async fn main() -> anyhow::Result<()> {
         .no_proxy()
         .build()
         .map_err(|e| anyhow::anyhow!("Failed to create client: {e:?}"))?;
-    log_cold_start_step("Creating the Extensions API client", step_start);
+    log_duration!(
+        COLD_START_DURATION,
+        "Creating the Extensions API client",
+        step_start
+    );
 
     let cloned_client = client.clone();
     let runtime_api = aws_config.runtime_api.clone();
@@ -159,7 +164,7 @@ async fn main() -> anyhow::Result<()> {
             managed_instance_mode,
         )
         .await;
-        log_cold_start_step("Registering the extension", step_start);
+        log_duration!(COLD_START_DURATION, "Registering the extension", step_start);
         response
     });
     // First load the AWS configuration
@@ -169,10 +174,14 @@ async fn main() -> anyhow::Result<()> {
 
     let step_start = Instant::now();
     let mut lambda_config = config::get_config(Path::new(&lambda_directory));
-    log_cold_start_step("Loading config", step_start);
+    log_duration!(COLD_START_DURATION, "Loading config", step_start);
     let step_start = Instant::now();
     resolve_additional_endpoints_secrets(&mut lambda_config, &aws_config).await;
-    log_cold_start_step("Resolving additional endpoint secrets", step_start);
+    log_duration!(
+        COLD_START_DURATION,
+        "Resolving additional endpoint secrets",
+        step_start
+    );
     let config = Arc::new(lambda_config);
 
     // Build one shared reqwest::Client for metrics, logs, trace proxy flushing, and calls to
@@ -186,7 +195,11 @@ async fn main() -> anyhow::Result<()> {
         .await
         .map_err(|e| anyhow::anyhow!("Failed to join task: {e:?}"))?
         .map_err(|e| anyhow::anyhow!("Failed to register extension: {e:?}"))?;
-    log_cold_start_step("Waiting for extension registration", step_start);
+    log_duration!(
+        COLD_START_DURATION,
+        "Waiting for extension registration",
+        step_start
+    );
 
     match extension_loop_active(
         Arc::clone(&aws_config),
@@ -218,17 +231,6 @@ fn init_ustr() {
     });
 }
 
-/// Tracing target for the duration of each cold start step.
-const COLD_START_DURATION: &str = "cold_start_duration";
-
-fn log_cold_start_step(step: &str, step_start: Instant) {
-    debug!(
-        target: COLD_START_DURATION,
-        "{step} took {:.3}ms",
-        step_start.elapsed().as_secs_f64() * 1000.0
-    );
-}
-
 fn enable_logging_subsystem() {
     let log_level = LogLevel::from_str(
         std::env::var("DD_LOG_LEVEL")
@@ -367,7 +369,7 @@ async fn extension_loop_active(
         &shared_client,
     )
     .await;
-    log_cold_start_step("Starting DogStatsD", step_start);
+    log_duration!(COLD_START_DURATION, "Starting DogStatsD", step_start);
 
     let propagator = Arc::new(DatadogCompositePropagator::new(Arc::clone(config)));
 
@@ -444,7 +446,11 @@ async fn extension_loop_active(
             None
         }
     };
-    log_cold_start_step("Creating the AppSec processor", step_start);
+    log_duration!(
+        COLD_START_DURATION,
+        "Creating the AppSec processor",
+        step_start
+    );
 
     let (
         trace_agent_channel,
@@ -494,7 +500,11 @@ async fn extension_loop_active(
         aws_config.is_managed_instance_mode(),
     )
     .await?;
-    log_cold_start_step("Starting the telemetry listener", step_start);
+    log_duration!(
+        COLD_START_DURATION,
+        "Starting the telemetry listener",
+        step_start
+    );
 
     let otlp_cancel_token = start_otlp_agent(
         config,
diff --git a/bottlecap/src/logger.rs b/bottlecap/src/logger.rs
index b9a828fc7..1752e2f97 100644
--- a/bottlecap/src/logger.rs
+++ b/bottlecap/src/logger.rs
@@ -6,6 +6,23 @@ use tracing_subscriber::fmt::{
 };
 use tracing_subscriber::registry::LookupSpan;
 
+/// Tracing target for the duration of each cold start step.
+pub const COLD_START_DURATION: &str = "cold_start_duration";
+
+/// Logs at debug level how long `step` took since `start`, under a duration target such as
+/// [`COLD_START_DURATION`]. A macro, because `tracing` needs the target as a constant.
+#[macro_export]
+macro_rules! log_duration {
+    ($target:expr, $step:expr, $start:expr) => {
+        tracing::debug!(
+            target: $target,
+            "{} took {:.3}ms",
+            $step,
+            $start.elapsed().as_secs_f64() * 1000.0
+        )
+    };
+}
+
 /// 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 {

From b231f9502cc5f81e4156dc2c9e3f39bc355bfcff Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Wed, 14 Oct 2026 14:52:18 -0400
Subject: [PATCH 03/11] [SVLS-9883] Log all cold start step durations in one
 JSON line

Replace the per-step debug lines with one "Cold start step durations"
line. Each step is a numeric field under a nested `cold_start` object,
rounded to 2 decimals, so that Datadog can graph and filter each step.

The steps are collected in a ColdStartDurations struct. It replaces the
`start_time` parameter of extension_loop_active, so the function keeps
7 parameters. The registration task returns its duration with its
result.

logger::Formatter writes the fields of an event as JSON values, and
nests a field named `group.key` under `group`. It used to drop every
field except the message. No other log call passes fields.

The summary line uses `event!`, because `debug!` in tracing 0.1.44
cannot parse dotted field names after `target:`.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/bin/bottlecap/main.rs | 120 +++++++++++++-------
 bottlecap/src/logger.rs             | 165 ++++++++++++++++++++++++----
 2 files changed, 223 insertions(+), 62 deletions(-)

diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs
index 7aca77a3f..d3ed34344 100644
--- a/bottlecap/src/bin/bottlecap/main.rs
+++ b/bottlecap/src/bin/bottlecap/main.rs
@@ -44,7 +44,6 @@ use bottlecap::{
         invocation::processor_service::{InvocationProcessorHandle, InvocationProcessorService},
         listener::Listener as LifecycleListener,
     },
-    log_duration,
     logger::{self, COLD_START_DURATION},
     logs::{
         agent::LogsAgent,
@@ -118,14 +117,14 @@ fn resolve_dsm_service(
 
 #[tokio::main]
 async fn main() -> anyhow::Result<()> {
-    let start_time = Instant::now();
+    let mut cold_start = ColdStartDurations::new(Instant::now());
     init_ustr();
     enable_logging_subsystem();
-    log_duration!(COLD_START_DURATION, "Enabling logging", start_time);
+    cold_start.enable_logging_ms = elapsed_ms(cold_start.start);
     let step_start = Instant::now();
-    let aws_config = AwsConfig::from_env(start_time);
+    let aws_config = AwsConfig::from_env(cold_start.start);
     log_fips_status(&aws_config.region);
-    log_duration!(COLD_START_DURATION, "Loading AWS config", step_start);
+    cold_start.load_aws_config_ms = elapsed_ms(step_start);
     let version_without_next = EXTENSION_VERSION.split('-').next().unwrap_or("NA");
     debug!("Starting Datadog Extension v{version_without_next}");
 
@@ -146,11 +145,7 @@ async fn main() -> anyhow::Result<()> {
         .no_proxy()
         .build()
         .map_err(|e| anyhow::anyhow!("Failed to create client: {e:?}"))?;
-    log_duration!(
-        COLD_START_DURATION,
-        "Creating the Extensions API client",
-        step_start
-    );
+    cold_start.create_extensions_api_client_ms = elapsed_ms(step_start);
 
     let cloned_client = client.clone();
     let runtime_api = aws_config.runtime_api.clone();
@@ -164,8 +159,7 @@ async fn main() -> anyhow::Result<()> {
             managed_instance_mode,
         )
         .await;
-        log_duration!(COLD_START_DURATION, "Registering the extension", step_start);
-        response
+        (response, elapsed_ms(step_start))
     });
     // First load the AWS configuration
     let lambda_directory: String =
@@ -174,14 +168,10 @@ async fn main() -> anyhow::Result<()> {
 
     let step_start = Instant::now();
     let mut lambda_config = config::get_config(Path::new(&lambda_directory));
-    log_duration!(COLD_START_DURATION, "Loading config", step_start);
+    cold_start.load_config_ms = elapsed_ms(step_start);
     let step_start = Instant::now();
     resolve_additional_endpoints_secrets(&mut lambda_config, &aws_config).await;
-    log_duration!(
-        COLD_START_DURATION,
-        "Resolving additional endpoint secrets",
-        step_start
-    );
+    cold_start.resolve_additional_endpoint_secrets_ms = elapsed_ms(step_start);
     let config = Arc::new(lambda_config);
 
     // Build one shared reqwest::Client for metrics, logs, trace proxy flushing, and calls to
@@ -191,15 +181,12 @@ async fn main() -> anyhow::Result<()> {
     let api_key_factory = create_api_key_factory(&config, &aws_config, &shared_client);
 
     let step_start = Instant::now();
-    let r = response
+    let (response, register_extension_ms) = response
         .await
-        .map_err(|e| anyhow::anyhow!("Failed to join task: {e:?}"))?
-        .map_err(|e| anyhow::anyhow!("Failed to register extension: {e:?}"))?;
-    log_duration!(
-        COLD_START_DURATION,
-        "Waiting for extension registration",
-        step_start
-    );
+        .map_err(|e| anyhow::anyhow!("Failed to join task: {e:?}"))?;
+    let r = response.map_err(|e| anyhow::anyhow!("Failed to register extension: {e:?}"))?;
+    cold_start.register_extension_ms = register_extension_ms;
+    cold_start.wait_for_register_ms = elapsed_ms(step_start);
 
     match extension_loop_active(
         Arc::clone(&aws_config),
@@ -208,7 +195,7 @@ async fn main() -> anyhow::Result<()> {
         shared_client,
         &r,
         Arc::clone(&api_key_factory),
-        start_time,
+        cold_start,
     )
     .await
     {
@@ -231,6 +218,66 @@ fn init_ustr() {
     });
 }
 
+/// Duration of each cold start step in milliseconds. The steps go in one log line as numeric
+/// fields, so that Datadog can graph each step.
+struct ColdStartDurations {
+    start: Instant,
+    enable_logging_ms: f64,
+    load_aws_config_ms: f64,
+    create_extensions_api_client_ms: f64,
+    register_extension_ms: f64,
+    load_config_ms: f64,
+    resolve_additional_endpoint_secrets_ms: f64,
+    wait_for_register_ms: f64,
+    start_dogstatsd_ms: f64,
+    create_appsec_processor_ms: f64,
+    start_telemetry_listener_ms: f64,
+}
+
+impl ColdStartDurations {
+    fn new(start: Instant) -> Self {
+        Self {
+            start,
+            enable_logging_ms: 0.0,
+            load_aws_config_ms: 0.0,
+            create_extensions_api_client_ms: 0.0,
+            register_extension_ms: 0.0,
+            load_config_ms: 0.0,
+            resolve_additional_endpoint_secrets_ms: 0.0,
+            wait_for_register_ms: 0.0,
+            start_dogstatsd_ms: 0.0,
+            create_appsec_processor_ms: 0.0,
+            start_telemetry_listener_ms: 0.0,
+        }
+    }
+
+    fn log(&self) {
+        // `debug!` cannot parse dotted field names after `target:`, so this uses `event!`.
+        tracing::event!(
+            target: COLD_START_DURATION,
+            tracing::Level::DEBUG,
+            cold_start.total_ms = elapsed_ms(self.start),
+            cold_start.enable_logging_ms = self.enable_logging_ms,
+            cold_start.load_aws_config_ms = self.load_aws_config_ms,
+            cold_start.create_extensions_api_client_ms = self.create_extensions_api_client_ms,
+            cold_start.register_extension_ms = self.register_extension_ms,
+            cold_start.load_config_ms = self.load_config_ms,
+            cold_start.resolve_additional_endpoint_secrets_ms =
+                self.resolve_additional_endpoint_secrets_ms,
+            cold_start.wait_for_register_ms = self.wait_for_register_ms,
+            cold_start.start_dogstatsd_ms = self.start_dogstatsd_ms,
+            cold_start.create_appsec_processor_ms = self.create_appsec_processor_ms,
+            cold_start.start_telemetry_listener_ms = self.start_telemetry_listener_ms,
+            "Cold start step durations"
+        );
+    }
+}
+
+/// Milliseconds since `start`, rounded to 2 decimals.
+fn elapsed_ms(start: Instant) -> f64 {
+    (start.elapsed().as_secs_f64() * 100_000.0).round() / 100.0
+}
+
 fn enable_logging_subsystem() {
     let log_level = LogLevel::from_str(
         std::env::var("DD_LOG_LEVEL")
@@ -339,7 +386,7 @@ async fn extension_loop_active(
     shared_client: reqwest::Client,
     r: &RegisterResponse,
     api_key_factory: Arc<ApiKeyFactory>,
-    start_time: Instant,
+    mut cold_start: ColdStartDurations,
 ) -> anyhow::Result<()> {
     let (mut event_bus, event_bus_tx) = EventBus::run();
 
@@ -369,7 +416,7 @@ async fn extension_loop_active(
         &shared_client,
     )
     .await;
-    log_duration!(COLD_START_DURATION, "Starting DogStatsD", step_start);
+    cold_start.start_dogstatsd_ms = elapsed_ms(step_start);
 
     let propagator = Arc::new(DatadogCompositePropagator::new(Arc::clone(config)));
 
@@ -446,11 +493,7 @@ async fn extension_loop_active(
             None
         }
     };
-    log_duration!(
-        COLD_START_DURATION,
-        "Creating the AppSec processor",
-        step_start
-    );
+    cold_start.create_appsec_processor_ms = elapsed_ms(step_start);
 
     let (
         trace_agent_channel,
@@ -500,11 +543,7 @@ async fn extension_loop_active(
         aws_config.is_managed_instance_mode(),
     )
     .await?;
-    log_duration!(
-        COLD_START_DURATION,
-        "Starting the telemetry listener",
-        step_start
-    );
+    cold_start.start_telemetry_listener_ms = elapsed_ms(step_start);
 
     let otlp_cancel_token = start_otlp_agent(
         config,
@@ -523,8 +562,9 @@ async fn extension_loop_active(
     debug!(
         target: COLD_START_DURATION,
         "Datadog Next-Gen Extension ready in {:}ms",
-        start_time.elapsed().as_millis().to_string()
+        cold_start.start.elapsed().as_millis().to_string()
     );
+    cold_start.log();
 
     if aws_config.is_managed_instance_mode() {
         // Clone Arc references for the background flusher task
diff --git a/bottlecap/src/logger.rs b/bottlecap/src/logger.rs
index 1752e2f97..0c804db6f 100644
--- a/bottlecap/src/logger.rs
+++ b/bottlecap/src/logger.rs
@@ -9,20 +9,6 @@ use tracing_subscriber::registry::LookupSpan;
 /// Tracing target for the duration of each cold start step.
 pub const COLD_START_DURATION: &str = "cold_start_duration";
 
-/// Logs at debug level how long `step` took since `start`, under a duration target such as
-/// [`COLD_START_DURATION`]. A macro, because `tracing` needs the target as a constant.
-#[macro_export]
-macro_rules! log_duration {
-    ($target:expr, $step:expr, $start:expr) => {
-        tracing::debug!(
-            target: $target,
-            "{} took {:.3}ms",
-            $step,
-            $start.elapsed().as_secs_f64() * 1000.0
-        )
-    };
-}
-
 /// 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 {
@@ -43,21 +29,98 @@ fn write_json_escaped(w: &mut impl fmt::Write, s: &str) -> fmt::Result {
 #[derive(Debug, Clone, Copy)]
 pub struct Formatter;
 
-/// Visitor that captures the message from tracing event fields.
-struct MessageVisitor(String);
+/// Visitor that captures the message and the other fields of a tracing event. Each other field
+/// becomes a JSON value, so that Datadog parses numbers as numbers.
+#[derive(Default)]
+struct FieldVisitor {
+    message: String,
+    /// Field names and JSON values, in the order of the event.
+    fields: Vec<(&'static str, String)>,
+}
 
-impl tracing::field::Visit for MessageVisitor {
+impl FieldVisitor {
+    fn push_string(&mut self, field: &tracing::field::Field, value: &str) {
+        let mut json = String::from("\"");
+        // Writing to a `String` cannot fail.
+        let _ = write_json_escaped(&mut json, value);
+        json.push('"');
+        self.fields.push((field.name(), json));
+    }
+}
+
+impl tracing::field::Visit for FieldVisitor {
     fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn fmt::Debug) {
         if field.name() == "message" {
-            self.0 = format!("{value:?}");
+            self.message = format!("{value:?}");
+        } else {
+            self.push_string(field, &format!("{value:?}"));
         }
     }
 
     fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
         if field.name() == "message" {
-            self.0 = value.to_string();
+            self.message = value.to_string();
+        } else {
+            self.push_string(field, value);
+        }
+    }
+
+    fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
+        // JSON has no NaN or infinity, so write those as strings.
+        if value.is_finite() {
+            self.fields.push((field.name(), value.to_string()));
+        } else {
+            self.push_string(field, &value.to_string());
+        }
+    }
+
+    fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
+        self.fields.push((field.name(), value.to_string()));
+    }
+
+    fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
+        self.fields.push((field.name(), value.to_string()));
+    }
+
+    fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
+        self.fields.push((field.name(), value.to_string()));
+    }
+}
+
+/// Writes `fields` as JSON members, each one preceded by a comma. A field named `group.key`
+/// goes into a nested `"group": {"key": ...}` object.
+fn write_json_fields(w: &mut impl fmt::Write, fields: &[(&'static str, String)]) -> fmt::Result {
+    let mut written_groups: Vec<&str> = Vec::new();
+    for (name, value) in fields {
+        match name.split_once('.') {
+            None => {
+                w.write_str(",\"")?;
+                write_json_escaped(w, name)?;
+                write!(w, "\":{value}")?;
+            }
+            Some((group, _)) => {
+                if written_groups.contains(&group) {
+                    continue;
+                }
+                written_groups.push(group);
+                w.write_str(",\"")?;
+                write_json_escaped(w, group)?;
+                w.write_str("\":{")?;
+                let members = fields.iter().filter_map(|(n, v)| {
+                    n.split_once('.')
+                        .filter(|(g, _)| *g == group)
+                        .map(|(_, k)| (k, v))
+                });
+                for (i, (key, value)) in members.enumerate() {
+                    w.write_str(if i == 0 { "\"" } else { ",\"" })?;
+                    write_json_escaped(w, key)?;
+                    write!(w, "\":{value}")?;
+                }
+                w.write_str("}")?;
+            }
         }
     }
+    Ok(())
 }
 
 impl<S, N> FormatEvent<S, N> for Formatter
@@ -74,7 +137,7 @@ where
         let metadata = event.metadata();
         let level = metadata.level();
 
-        let mut visitor = MessageVisitor(String::new());
+        let mut visitor = FieldVisitor::default();
         event.record(&mut visitor);
 
         // Build span context prefix
@@ -94,14 +157,16 @@ where
             }
         }
 
-        let message = format!("DD_EXTENSION | {level} | {span_prefix}{}", visitor.0);
+        let message = format!("DD_EXTENSION | {level} | {span_prefix}{}", 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\":\"")?;
         write_json_escaped(&mut writer, &message)?;
-        writeln!(writer, "\"}}")
+        writer.write_char('"')?;
+        write_json_fields(&mut writer, &visitor.fields)?;
+        writeln!(writer, "}}")
     }
 }
 
@@ -281,4 +346,60 @@ mod tests {
             "parsed message should contain literal newline"
         );
     }
+
+    #[test]
+    fn test_formatter_nests_grouped_fields_as_numbers() {
+        let output = capture_log(|| {
+            tracing::event!(
+                tracing::Level::DEBUG,
+                cold_start.total_ms = 21.0_f64,
+                cold_start.load_config_ms = 1.61_f64,
+                "durations"
+            );
+        });
+
+        let parsed: serde_json::Value =
+            serde_json::from_str(output.trim()).expect("output should be valid JSON");
+
+        assert_eq!(parsed["cold_start"]["total_ms"].as_f64(), Some(21.0));
+        assert_eq!(parsed["cold_start"]["load_config_ms"].as_f64(), Some(1.61));
+        assert!(
+            parsed["message"]
+                .as_str()
+                .unwrap()
+                .contains("DD_EXTENSION | DEBUG | durations")
+        );
+    }
+
+    #[test]
+    fn test_formatter_omits_none_fields() {
+        let output = capture_log(|| {
+            tracing::event!(
+                tracing::Level::DEBUG,
+                cold_start.secrets_ms = None::<f64>,
+                cold_start.load_config_ms = 1.5_f64,
+                "durations"
+            );
+        });
+
+        let parsed: serde_json::Value =
+            serde_json::from_str(output.trim()).expect("output should be valid JSON");
+
+        assert!(parsed["cold_start"].get("secrets_ms").is_none());
+        assert_eq!(parsed["cold_start"]["load_config_ms"].as_f64(), Some(1.5));
+    }
+
+    #[test]
+    fn test_formatter_writes_flat_fields_by_type() {
+        let output = capture_log(|| {
+            tracing::info!(count = 3_u64, ok = true, name = "a \"b\"", "fields");
+        });
+
+        let parsed: serde_json::Value =
+            serde_json::from_str(output.trim()).expect("output should be valid JSON");
+
+        assert_eq!(parsed["count"].as_u64(), Some(3));
+        assert_eq!(parsed["ok"].as_bool(), Some(true));
+        assert_eq!(parsed["name"].as_str(), Some("a \"b\""));
+    }
 }

From 85404bfa9e4c51112a65e4a259b5568ec91af388 Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Thu, 15 Oct 2026 14:52:34 -0400
Subject: [PATCH 04/11] [SVLS-9883] Move ColdStartDurations to its own module
 and rename timers

ColdStartDurations, its log() method and elapsed_ms() move from main.rs
to bottlecap::cold_start, so main.rs keeps only the timing calls.

Renames: `cold_start` to `cold_start_durations`, its field `start` to
`started_at`, and `step_start` to `step_started_at`.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/bin/bottlecap/main.rs | 113 +++++++---------------------
 bottlecap/src/cold_start.rs         |  68 +++++++++++++++++
 bottlecap/src/lib.rs                |   1 +
 3 files changed, 96 insertions(+), 86 deletions(-)
 create mode 100644 bottlecap/src/cold_start.rs

diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs
index d3ed34344..88b9812ea 100644
--- a/bottlecap/src/bin/bottlecap/main.rs
+++ b/bottlecap/src/bin/bottlecap/main.rs
@@ -21,6 +21,7 @@ use bottlecap::{
     appsec::processor::{
         Error::FeatureDisabled as AppSecFeatureDisabled, Processor as AppSecProcessor,
     },
+    cold_start::{ColdStartDurations, elapsed_ms},
     config::{
         self, Config,
         aws::{AwsConfig, build_lambda_function_arn},
@@ -117,14 +118,14 @@ fn resolve_dsm_service(
 
 #[tokio::main]
 async fn main() -> anyhow::Result<()> {
-    let mut cold_start = ColdStartDurations::new(Instant::now());
+    let mut cold_start_durations = ColdStartDurations::new(Instant::now());
     init_ustr();
     enable_logging_subsystem();
-    cold_start.enable_logging_ms = elapsed_ms(cold_start.start);
-    let step_start = Instant::now();
-    let aws_config = AwsConfig::from_env(cold_start.start);
+    cold_start_durations.enable_logging_ms = elapsed_ms(cold_start_durations.started_at);
+    let step_started_at = Instant::now();
+    let aws_config = AwsConfig::from_env(cold_start_durations.started_at);
     log_fips_status(&aws_config.region);
-    cold_start.load_aws_config_ms = elapsed_ms(step_start);
+    cold_start_durations.load_aws_config_ms = elapsed_ms(step_started_at);
     let version_without_next = EXTENSION_VERSION.split('-').next().unwrap_or("NA");
     debug!("Starting Datadog Extension v{version_without_next}");
 
@@ -138,20 +139,20 @@ async fn main() -> anyhow::Result<()> {
         debug!("DD_DEBUG_WAIT_FOR_ATTACH: Continuing execution...");
     }
 
-    let step_start = Instant::now();
+    let step_started_at = Instant::now();
     prepare_client_provider()?;
     let client = create_reqwest_client_builder()
         .map_err(|e| anyhow::anyhow!("Failed to create client builder: {e:?}"))?
         .no_proxy()
         .build()
         .map_err(|e| anyhow::anyhow!("Failed to create client: {e:?}"))?;
-    cold_start.create_extensions_api_client_ms = elapsed_ms(step_start);
+    cold_start_durations.create_extensions_api_client_ms = elapsed_ms(step_started_at);
 
     let cloned_client = client.clone();
     let runtime_api = aws_config.runtime_api.clone();
     let managed_instance_mode = aws_config.is_managed_instance_mode();
     let response = tokio::task::spawn(async move {
-        let step_start = Instant::now();
+        let step_started_at = Instant::now();
         let response = extension::register(
             &cloned_client,
             &runtime_api,
@@ -159,19 +160,19 @@ async fn main() -> anyhow::Result<()> {
             managed_instance_mode,
         )
         .await;
-        (response, elapsed_ms(step_start))
+        (response, elapsed_ms(step_started_at))
     });
     // First load the AWS configuration
     let lambda_directory: String =
         env::var("LAMBDA_TASK_ROOT").unwrap_or_else(|_| "/var/task".to_string());
     let aws_config = Arc::new(aws_config);
 
-    let step_start = Instant::now();
+    let step_started_at = Instant::now();
     let mut lambda_config = config::get_config(Path::new(&lambda_directory));
-    cold_start.load_config_ms = elapsed_ms(step_start);
-    let step_start = Instant::now();
+    cold_start_durations.load_config_ms = elapsed_ms(step_started_at);
+    let step_started_at = Instant::now();
     resolve_additional_endpoints_secrets(&mut lambda_config, &aws_config).await;
-    cold_start.resolve_additional_endpoint_secrets_ms = elapsed_ms(step_start);
+    cold_start_durations.resolve_additional_endpoint_secrets_ms = elapsed_ms(step_started_at);
     let config = Arc::new(lambda_config);
 
     // Build one shared reqwest::Client for metrics, logs, trace proxy flushing, and calls to
@@ -180,13 +181,13 @@ async fn main() -> anyhow::Result<()> {
     let shared_client = bottlecap::http::get_client(&config);
     let api_key_factory = create_api_key_factory(&config, &aws_config, &shared_client);
 
-    let step_start = Instant::now();
+    let step_started_at = Instant::now();
     let (response, register_extension_ms) = response
         .await
         .map_err(|e| anyhow::anyhow!("Failed to join task: {e:?}"))?;
     let r = response.map_err(|e| anyhow::anyhow!("Failed to register extension: {e:?}"))?;
-    cold_start.register_extension_ms = register_extension_ms;
-    cold_start.wait_for_register_ms = elapsed_ms(step_start);
+    cold_start_durations.register_extension_ms = register_extension_ms;
+    cold_start_durations.wait_for_register_ms = elapsed_ms(step_started_at);
 
     match extension_loop_active(
         Arc::clone(&aws_config),
@@ -195,7 +196,7 @@ async fn main() -> anyhow::Result<()> {
         shared_client,
         &r,
         Arc::clone(&api_key_factory),
-        cold_start,
+        cold_start_durations,
     )
     .await
     {
@@ -218,66 +219,6 @@ fn init_ustr() {
     });
 }
 
-/// Duration of each cold start step in milliseconds. The steps go in one log line as numeric
-/// fields, so that Datadog can graph each step.
-struct ColdStartDurations {
-    start: Instant,
-    enable_logging_ms: f64,
-    load_aws_config_ms: f64,
-    create_extensions_api_client_ms: f64,
-    register_extension_ms: f64,
-    load_config_ms: f64,
-    resolve_additional_endpoint_secrets_ms: f64,
-    wait_for_register_ms: f64,
-    start_dogstatsd_ms: f64,
-    create_appsec_processor_ms: f64,
-    start_telemetry_listener_ms: f64,
-}
-
-impl ColdStartDurations {
-    fn new(start: Instant) -> Self {
-        Self {
-            start,
-            enable_logging_ms: 0.0,
-            load_aws_config_ms: 0.0,
-            create_extensions_api_client_ms: 0.0,
-            register_extension_ms: 0.0,
-            load_config_ms: 0.0,
-            resolve_additional_endpoint_secrets_ms: 0.0,
-            wait_for_register_ms: 0.0,
-            start_dogstatsd_ms: 0.0,
-            create_appsec_processor_ms: 0.0,
-            start_telemetry_listener_ms: 0.0,
-        }
-    }
-
-    fn log(&self) {
-        // `debug!` cannot parse dotted field names after `target:`, so this uses `event!`.
-        tracing::event!(
-            target: COLD_START_DURATION,
-            tracing::Level::DEBUG,
-            cold_start.total_ms = elapsed_ms(self.start),
-            cold_start.enable_logging_ms = self.enable_logging_ms,
-            cold_start.load_aws_config_ms = self.load_aws_config_ms,
-            cold_start.create_extensions_api_client_ms = self.create_extensions_api_client_ms,
-            cold_start.register_extension_ms = self.register_extension_ms,
-            cold_start.load_config_ms = self.load_config_ms,
-            cold_start.resolve_additional_endpoint_secrets_ms =
-                self.resolve_additional_endpoint_secrets_ms,
-            cold_start.wait_for_register_ms = self.wait_for_register_ms,
-            cold_start.start_dogstatsd_ms = self.start_dogstatsd_ms,
-            cold_start.create_appsec_processor_ms = self.create_appsec_processor_ms,
-            cold_start.start_telemetry_listener_ms = self.start_telemetry_listener_ms,
-            "Cold start step durations"
-        );
-    }
-}
-
-/// Milliseconds since `start`, rounded to 2 decimals.
-fn elapsed_ms(start: Instant) -> f64 {
-    (start.elapsed().as_secs_f64() * 100_000.0).round() / 100.0
-}
-
 fn enable_logging_subsystem() {
     let log_level = LogLevel::from_str(
         std::env::var("DD_LOG_LEVEL")
@@ -386,7 +327,7 @@ async fn extension_loop_active(
     shared_client: reqwest::Client,
     r: &RegisterResponse,
     api_key_factory: Arc<ApiKeyFactory>,
-    mut cold_start: ColdStartDurations,
+    mut cold_start_durations: ColdStartDurations,
 ) -> anyhow::Result<()> {
     let (mut event_bus, event_bus_tx) = EventBus::run();
 
@@ -408,7 +349,7 @@ async fn extension_loop_active(
         &shared_client,
     );
 
-    let step_start = Instant::now();
+    let step_started_at = Instant::now();
     let (metrics_flushers, metrics_aggregator_handle, dogstatsd_cancel_token) = start_dogstatsd(
         tags_provider.clone(),
         Arc::clone(&api_key_factory),
@@ -416,7 +357,7 @@ async fn extension_loop_active(
         &shared_client,
     )
     .await;
-    cold_start.start_dogstatsd_ms = elapsed_ms(step_start);
+    cold_start_durations.start_dogstatsd_ms = elapsed_ms(step_started_at);
 
     let propagator = Arc::new(DatadogCompositePropagator::new(Arc::clone(config)));
 
@@ -482,7 +423,7 @@ async fn extension_loop_active(
     });
 
     // AppSec processor (if enabled)
-    let step_start = Instant::now();
+    let step_started_at = Instant::now();
     let appsec_processor = match AppSecProcessor::new(config) {
         Ok(p) => Some(Arc::new(TokioMutex::new(p))),
         Err(AppSecFeatureDisabled) => None,
@@ -493,7 +434,7 @@ async fn extension_loop_active(
             None
         }
     };
-    cold_start.create_appsec_processor_ms = elapsed_ms(step_start);
+    cold_start_durations.create_appsec_processor_ms = elapsed_ms(step_started_at);
 
     let (
         trace_agent_channel,
@@ -532,7 +473,7 @@ async fn extension_loop_active(
         }
     });
 
-    let step_start = Instant::now();
+    let step_started_at = Instant::now();
     let telemetry_listener_cancel_token = setup_telemetry_client(
         client,
         &r.extension_id,
@@ -543,7 +484,7 @@ async fn extension_loop_active(
         aws_config.is_managed_instance_mode(),
     )
     .await?;
-    cold_start.start_telemetry_listener_ms = elapsed_ms(step_start);
+    cold_start_durations.start_telemetry_listener_ms = elapsed_ms(step_started_at);
 
     let otlp_cancel_token = start_otlp_agent(
         config,
@@ -562,9 +503,9 @@ async fn extension_loop_active(
     debug!(
         target: COLD_START_DURATION,
         "Datadog Next-Gen Extension ready in {:}ms",
-        cold_start.start.elapsed().as_millis().to_string()
+        cold_start_durations.started_at.elapsed().as_millis().to_string()
     );
-    cold_start.log();
+    cold_start_durations.log();
 
     if aws_config.is_managed_instance_mode() {
         // Clone Arc references for the background flusher task
diff --git a/bottlecap/src/cold_start.rs b/bottlecap/src/cold_start.rs
new file mode 100644
index 000000000..17471d221
--- /dev/null
+++ b/bottlecap/src/cold_start.rs
@@ -0,0 +1,68 @@
+use tokio::time::Instant;
+
+use crate::logger::COLD_START_DURATION;
+
+/// Duration of each cold start step in milliseconds. The steps go in one log line as numeric
+/// fields, so that Datadog can graph each step.
+#[derive(Debug, Clone, Copy)]
+pub struct ColdStartDurations {
+    /// When the extension process started.
+    pub started_at: Instant,
+    pub enable_logging_ms: f64,
+    pub load_aws_config_ms: f64,
+    pub create_extensions_api_client_ms: f64,
+    pub register_extension_ms: f64,
+    pub load_config_ms: f64,
+    pub resolve_additional_endpoint_secrets_ms: f64,
+    pub wait_for_register_ms: f64,
+    pub start_dogstatsd_ms: f64,
+    pub create_appsec_processor_ms: f64,
+    pub start_telemetry_listener_ms: f64,
+}
+
+impl ColdStartDurations {
+    #[must_use]
+    pub fn new(started_at: Instant) -> Self {
+        Self {
+            started_at,
+            enable_logging_ms: 0.0,
+            load_aws_config_ms: 0.0,
+            create_extensions_api_client_ms: 0.0,
+            register_extension_ms: 0.0,
+            load_config_ms: 0.0,
+            resolve_additional_endpoint_secrets_ms: 0.0,
+            wait_for_register_ms: 0.0,
+            start_dogstatsd_ms: 0.0,
+            create_appsec_processor_ms: 0.0,
+            start_telemetry_listener_ms: 0.0,
+        }
+    }
+
+    /// Logs all durations in one line, with the time since `started_at` as the total.
+    pub fn log(&self) {
+        // `debug!` cannot parse dotted field names after `target:`, so this uses `event!`.
+        tracing::event!(
+            target: COLD_START_DURATION,
+            tracing::Level::DEBUG,
+            cold_start.total_ms = elapsed_ms(self.started_at),
+            cold_start.enable_logging_ms = self.enable_logging_ms,
+            cold_start.load_aws_config_ms = self.load_aws_config_ms,
+            cold_start.create_extensions_api_client_ms = self.create_extensions_api_client_ms,
+            cold_start.register_extension_ms = self.register_extension_ms,
+            cold_start.load_config_ms = self.load_config_ms,
+            cold_start.resolve_additional_endpoint_secrets_ms =
+                self.resolve_additional_endpoint_secrets_ms,
+            cold_start.wait_for_register_ms = self.wait_for_register_ms,
+            cold_start.start_dogstatsd_ms = self.start_dogstatsd_ms,
+            cold_start.create_appsec_processor_ms = self.create_appsec_processor_ms,
+            cold_start.start_telemetry_listener_ms = self.start_telemetry_listener_ms,
+            "Cold start step durations"
+        );
+    }
+}
+
+/// Milliseconds since `started_at`, rounded to 2 decimals.
+#[must_use]
+pub fn elapsed_ms(started_at: Instant) -> f64 {
+    (started_at.elapsed().as_secs_f64() * 100_000.0).round() / 100.0
+}
diff --git a/bottlecap/src/lib.rs b/bottlecap/src/lib.rs
index df94fd246..0ae8b5749 100644
--- a/bottlecap/src/lib.rs
+++ b/bottlecap/src/lib.rs
@@ -20,6 +20,7 @@
 #![cfg_attr(coverage_nightly, feature(coverage_attribute))]
 
 pub mod appsec;
+pub mod cold_start;
 pub mod config;
 pub mod event_bus;
 pub mod extension;

From 9455f1c896748e90b2335a86bfc04a5db0226735 Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Thu, 15 Oct 2026 15:11:24 -0400
Subject: [PATCH 05/11] [SVLS-9883] Keep "ready in" on the default target

Support and engineers search for this line, and on the
cold_start_duration target a DD_LOG_LEVEL_BY_TARGET entry such as
`cold_start_duration=off` would hide it. The summary line already has
the total as `total_ms`.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/bin/bottlecap/main.rs | 9 ++++++---
 1 file changed, 6 insertions(+), 3 deletions(-)

diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs
index 88b9812ea..b9584ef01 100644
--- a/bottlecap/src/bin/bottlecap/main.rs
+++ b/bottlecap/src/bin/bottlecap/main.rs
@@ -45,7 +45,7 @@ use bottlecap::{
         invocation::processor_service::{InvocationProcessorHandle, InvocationProcessorService},
         listener::Listener as LifecycleListener,
     },
-    logger::{self, COLD_START_DURATION},
+    logger,
     logs::{
         agent::LogsAgent,
         aggregator_service::{
@@ -501,9 +501,12 @@ async fn extension_loop_active(
     let mut flush_control = FlushControl::new(flush_strategy, config.flush_timeout);
 
     debug!(
-        target: COLD_START_DURATION,
         "Datadog Next-Gen Extension ready in {:}ms",
-        cold_start_durations.started_at.elapsed().as_millis().to_string()
+        cold_start_durations
+            .started_at
+            .elapsed()
+            .as_millis()
+            .to_string()
     );
     cold_start_durations.log();
 

From 71e0a04ddb7522fd276a7268526010687ead91d1 Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Thu, 15 Oct 2026 15:15:49 -0400
Subject: [PATCH 06/11] [SVLS-9883] Rename the cold_start module to
 cold_start_log

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/bin/bottlecap/main.rs                | 2 +-
 bottlecap/src/{cold_start.rs => cold_start_log.rs} | 0
 bottlecap/src/lib.rs                               | 2 +-
 3 files changed, 2 insertions(+), 2 deletions(-)
 rename bottlecap/src/{cold_start.rs => cold_start_log.rs} (100%)

diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs
index b9584ef01..6d1f14517 100644
--- a/bottlecap/src/bin/bottlecap/main.rs
+++ b/bottlecap/src/bin/bottlecap/main.rs
@@ -21,7 +21,7 @@ use bottlecap::{
     appsec::processor::{
         Error::FeatureDisabled as AppSecFeatureDisabled, Processor as AppSecProcessor,
     },
-    cold_start::{ColdStartDurations, elapsed_ms},
+    cold_start_log::{ColdStartDurations, elapsed_ms},
     config::{
         self, Config,
         aws::{AwsConfig, build_lambda_function_arn},
diff --git a/bottlecap/src/cold_start.rs b/bottlecap/src/cold_start_log.rs
similarity index 100%
rename from bottlecap/src/cold_start.rs
rename to bottlecap/src/cold_start_log.rs
diff --git a/bottlecap/src/lib.rs b/bottlecap/src/lib.rs
index 0ae8b5749..566ec2123 100644
--- a/bottlecap/src/lib.rs
+++ b/bottlecap/src/lib.rs
@@ -20,7 +20,7 @@
 #![cfg_attr(coverage_nightly, feature(coverage_attribute))]
 
 pub mod appsec;
-pub mod cold_start;
+pub mod cold_start_log;
 pub mod config;
 pub mod event_bus;
 pub mod extension;

From 71c0efe1d29049bd09e1adb5d4d12d0ba674d4f8 Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Thu, 15 Oct 2026 15:21:34 -0400
Subject: [PATCH 07/11] [SVLS-9883] Move the extension's logging code into a
 logger/ folder

logger.rs becomes logger/mod.rs, and cold_start_log.rs becomes
logger/cold_start.rs, so the formatter, the log targets and the cold
start durations live together.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/bin/bottlecap/main.rs                       | 6 ++++--
 bottlecap/src/lib.rs                                      | 1 -
 bottlecap/src/{cold_start_log.rs => logger/cold_start.rs} | 2 +-
 bottlecap/src/{logger.rs => logger/mod.rs}                | 2 ++
 4 files changed, 7 insertions(+), 4 deletions(-)
 rename bottlecap/src/{cold_start_log.rs => logger/cold_start.rs} (98%)
 rename bottlecap/src/{logger.rs => logger/mod.rs} (99%)

diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs
index 6d1f14517..65301c441 100644
--- a/bottlecap/src/bin/bottlecap/main.rs
+++ b/bottlecap/src/bin/bottlecap/main.rs
@@ -21,7 +21,6 @@ use bottlecap::{
     appsec::processor::{
         Error::FeatureDisabled as AppSecFeatureDisabled, Processor as AppSecProcessor,
     },
-    cold_start_log::{ColdStartDurations, elapsed_ms},
     config::{
         self, Config,
         aws::{AwsConfig, build_lambda_function_arn},
@@ -45,7 +44,10 @@ use bottlecap::{
         invocation::processor_service::{InvocationProcessorHandle, InvocationProcessorService},
         listener::Listener as LifecycleListener,
     },
-    logger,
+    logger::{
+        self,
+        cold_start::{ColdStartDurations, elapsed_ms},
+    },
     logs::{
         agent::LogsAgent,
         aggregator_service::{
diff --git a/bottlecap/src/lib.rs b/bottlecap/src/lib.rs
index 566ec2123..df94fd246 100644
--- a/bottlecap/src/lib.rs
+++ b/bottlecap/src/lib.rs
@@ -20,7 +20,6 @@
 #![cfg_attr(coverage_nightly, feature(coverage_attribute))]
 
 pub mod appsec;
-pub mod cold_start_log;
 pub mod config;
 pub mod event_bus;
 pub mod extension;
diff --git a/bottlecap/src/cold_start_log.rs b/bottlecap/src/logger/cold_start.rs
similarity index 98%
rename from bottlecap/src/cold_start_log.rs
rename to bottlecap/src/logger/cold_start.rs
index 17471d221..eedb9f51f 100644
--- a/bottlecap/src/cold_start_log.rs
+++ b/bottlecap/src/logger/cold_start.rs
@@ -1,6 +1,6 @@
 use tokio::time::Instant;
 
-use crate::logger::COLD_START_DURATION;
+use super::COLD_START_DURATION;
 
 /// Duration of each cold start step in milliseconds. The steps go in one log line as numeric
 /// fields, so that Datadog can graph each step.
diff --git a/bottlecap/src/logger.rs b/bottlecap/src/logger/mod.rs
similarity index 99%
rename from bottlecap/src/logger.rs
rename to bottlecap/src/logger/mod.rs
index 0c804db6f..daef942a1 100644
--- a/bottlecap/src/logger.rs
+++ b/bottlecap/src/logger/mod.rs
@@ -6,6 +6,8 @@ use tracing_subscriber::fmt::{
 };
 use tracing_subscriber::registry::LookupSpan;
 
+pub mod cold_start;
+
 /// Tracing target for the duration of each cold start step.
 pub const COLD_START_DURATION: &str = "cold_start_duration";
 

From 572c8755377fc04c38753ed1a4a6007fa91a6c6e Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Thu, 15 Oct 2026 15:27:57 -0400
Subject: [PATCH 08/11] [SVLS-9883] Name the cold start timers start_time and
 step_start_time

The codebase names Instant values start, start_time or *_time, and has
no *_at names. main.rs called the process start start_time before.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/bin/bottlecap/main.rs | 42 ++++++++++++++---------------
 bottlecap/src/logger/cold_start.rs  | 16 +++++------
 2 files changed, 29 insertions(+), 29 deletions(-)

diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs
index 65301c441..6471cded7 100644
--- a/bottlecap/src/bin/bottlecap/main.rs
+++ b/bottlecap/src/bin/bottlecap/main.rs
@@ -123,11 +123,11 @@ async fn main() -> anyhow::Result<()> {
     let mut cold_start_durations = ColdStartDurations::new(Instant::now());
     init_ustr();
     enable_logging_subsystem();
-    cold_start_durations.enable_logging_ms = elapsed_ms(cold_start_durations.started_at);
-    let step_started_at = Instant::now();
-    let aws_config = AwsConfig::from_env(cold_start_durations.started_at);
+    cold_start_durations.enable_logging_ms = elapsed_ms(cold_start_durations.start_time);
+    let step_start_time = Instant::now();
+    let aws_config = AwsConfig::from_env(cold_start_durations.start_time);
     log_fips_status(&aws_config.region);
-    cold_start_durations.load_aws_config_ms = elapsed_ms(step_started_at);
+    cold_start_durations.load_aws_config_ms = elapsed_ms(step_start_time);
     let version_without_next = EXTENSION_VERSION.split('-').next().unwrap_or("NA");
     debug!("Starting Datadog Extension v{version_without_next}");
 
@@ -141,20 +141,20 @@ async fn main() -> anyhow::Result<()> {
         debug!("DD_DEBUG_WAIT_FOR_ATTACH: Continuing execution...");
     }
 
-    let step_started_at = Instant::now();
+    let step_start_time = Instant::now();
     prepare_client_provider()?;
     let client = create_reqwest_client_builder()
         .map_err(|e| anyhow::anyhow!("Failed to create client builder: {e:?}"))?
         .no_proxy()
         .build()
         .map_err(|e| anyhow::anyhow!("Failed to create client: {e:?}"))?;
-    cold_start_durations.create_extensions_api_client_ms = elapsed_ms(step_started_at);
+    cold_start_durations.create_extensions_api_client_ms = elapsed_ms(step_start_time);
 
     let cloned_client = client.clone();
     let runtime_api = aws_config.runtime_api.clone();
     let managed_instance_mode = aws_config.is_managed_instance_mode();
     let response = tokio::task::spawn(async move {
-        let step_started_at = Instant::now();
+        let step_start_time = Instant::now();
         let response = extension::register(
             &cloned_client,
             &runtime_api,
@@ -162,19 +162,19 @@ async fn main() -> anyhow::Result<()> {
             managed_instance_mode,
         )
         .await;
-        (response, elapsed_ms(step_started_at))
+        (response, elapsed_ms(step_start_time))
     });
     // First load the AWS configuration
     let lambda_directory: String =
         env::var("LAMBDA_TASK_ROOT").unwrap_or_else(|_| "/var/task".to_string());
     let aws_config = Arc::new(aws_config);
 
-    let step_started_at = Instant::now();
+    let step_start_time = Instant::now();
     let mut lambda_config = config::get_config(Path::new(&lambda_directory));
-    cold_start_durations.load_config_ms = elapsed_ms(step_started_at);
-    let step_started_at = Instant::now();
+    cold_start_durations.load_config_ms = elapsed_ms(step_start_time);
+    let step_start_time = Instant::now();
     resolve_additional_endpoints_secrets(&mut lambda_config, &aws_config).await;
-    cold_start_durations.resolve_additional_endpoint_secrets_ms = elapsed_ms(step_started_at);
+    cold_start_durations.resolve_additional_endpoint_secrets_ms = elapsed_ms(step_start_time);
     let config = Arc::new(lambda_config);
 
     // Build one shared reqwest::Client for metrics, logs, trace proxy flushing, and calls to
@@ -183,13 +183,13 @@ async fn main() -> anyhow::Result<()> {
     let shared_client = bottlecap::http::get_client(&config);
     let api_key_factory = create_api_key_factory(&config, &aws_config, &shared_client);
 
-    let step_started_at = Instant::now();
+    let step_start_time = Instant::now();
     let (response, register_extension_ms) = response
         .await
         .map_err(|e| anyhow::anyhow!("Failed to join task: {e:?}"))?;
     let r = response.map_err(|e| anyhow::anyhow!("Failed to register extension: {e:?}"))?;
     cold_start_durations.register_extension_ms = register_extension_ms;
-    cold_start_durations.wait_for_register_ms = elapsed_ms(step_started_at);
+    cold_start_durations.wait_for_register_ms = elapsed_ms(step_start_time);
 
     match extension_loop_active(
         Arc::clone(&aws_config),
@@ -351,7 +351,7 @@ async fn extension_loop_active(
         &shared_client,
     );
 
-    let step_started_at = Instant::now();
+    let step_start_time = Instant::now();
     let (metrics_flushers, metrics_aggregator_handle, dogstatsd_cancel_token) = start_dogstatsd(
         tags_provider.clone(),
         Arc::clone(&api_key_factory),
@@ -359,7 +359,7 @@ async fn extension_loop_active(
         &shared_client,
     )
     .await;
-    cold_start_durations.start_dogstatsd_ms = elapsed_ms(step_started_at);
+    cold_start_durations.start_dogstatsd_ms = elapsed_ms(step_start_time);
 
     let propagator = Arc::new(DatadogCompositePropagator::new(Arc::clone(config)));
 
@@ -425,7 +425,7 @@ async fn extension_loop_active(
     });
 
     // AppSec processor (if enabled)
-    let step_started_at = Instant::now();
+    let step_start_time = Instant::now();
     let appsec_processor = match AppSecProcessor::new(config) {
         Ok(p) => Some(Arc::new(TokioMutex::new(p))),
         Err(AppSecFeatureDisabled) => None,
@@ -436,7 +436,7 @@ async fn extension_loop_active(
             None
         }
     };
-    cold_start_durations.create_appsec_processor_ms = elapsed_ms(step_started_at);
+    cold_start_durations.create_appsec_processor_ms = elapsed_ms(step_start_time);
 
     let (
         trace_agent_channel,
@@ -475,7 +475,7 @@ async fn extension_loop_active(
         }
     });
 
-    let step_started_at = Instant::now();
+    let step_start_time = Instant::now();
     let telemetry_listener_cancel_token = setup_telemetry_client(
         client,
         &r.extension_id,
@@ -486,7 +486,7 @@ async fn extension_loop_active(
         aws_config.is_managed_instance_mode(),
     )
     .await?;
-    cold_start_durations.start_telemetry_listener_ms = elapsed_ms(step_started_at);
+    cold_start_durations.start_telemetry_listener_ms = elapsed_ms(step_start_time);
 
     let otlp_cancel_token = start_otlp_agent(
         config,
@@ -505,7 +505,7 @@ async fn extension_loop_active(
     debug!(
         "Datadog Next-Gen Extension ready in {:}ms",
         cold_start_durations
-            .started_at
+            .start_time
             .elapsed()
             .as_millis()
             .to_string()
diff --git a/bottlecap/src/logger/cold_start.rs b/bottlecap/src/logger/cold_start.rs
index eedb9f51f..a917787c1 100644
--- a/bottlecap/src/logger/cold_start.rs
+++ b/bottlecap/src/logger/cold_start.rs
@@ -7,7 +7,7 @@ use super::COLD_START_DURATION;
 #[derive(Debug, Clone, Copy)]
 pub struct ColdStartDurations {
     /// When the extension process started.
-    pub started_at: Instant,
+    pub start_time: Instant,
     pub enable_logging_ms: f64,
     pub load_aws_config_ms: f64,
     pub create_extensions_api_client_ms: f64,
@@ -22,9 +22,9 @@ pub struct ColdStartDurations {
 
 impl ColdStartDurations {
     #[must_use]
-    pub fn new(started_at: Instant) -> Self {
+    pub fn new(start_time: Instant) -> Self {
         Self {
-            started_at,
+            start_time,
             enable_logging_ms: 0.0,
             load_aws_config_ms: 0.0,
             create_extensions_api_client_ms: 0.0,
@@ -38,13 +38,13 @@ impl ColdStartDurations {
         }
     }
 
-    /// Logs all durations in one line, with the time since `started_at` as the total.
+    /// Logs all durations in one line, with the time since `start_time` as the total.
     pub fn log(&self) {
         // `debug!` cannot parse dotted field names after `target:`, so this uses `event!`.
         tracing::event!(
             target: COLD_START_DURATION,
             tracing::Level::DEBUG,
-            cold_start.total_ms = elapsed_ms(self.started_at),
+            cold_start.total_ms = elapsed_ms(self.start_time),
             cold_start.enable_logging_ms = self.enable_logging_ms,
             cold_start.load_aws_config_ms = self.load_aws_config_ms,
             cold_start.create_extensions_api_client_ms = self.create_extensions_api_client_ms,
@@ -61,8 +61,8 @@ impl ColdStartDurations {
     }
 }
 
-/// Milliseconds since `started_at`, rounded to 2 decimals.
+/// Milliseconds since `start_time`, rounded to 2 decimals.
 #[must_use]
-pub fn elapsed_ms(started_at: Instant) -> f64 {
-    (started_at.elapsed().as_secs_f64() * 100_000.0).round() / 100.0
+pub fn elapsed_ms(start_time: Instant) -> f64 {
+    (start_time.elapsed().as_secs_f64() * 100_000.0).round() / 100.0
 }

From f68f809319811c454023d6319caa9ad136d4b4a0 Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Thu, 15 Oct 2026 15:51:02 -0400
Subject: [PATCH 09/11] [SVLS-9883] Write only f64 fields in the log formatter

The summary line has only f64 fields, so the formatter writes those and
drops the other field types, as it did before for all fields. Strings,
integers and booleans need their own record_* method when a log line
first uses them. A NaN or infinite value is dropped, because JSON has no
value for it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/logger/mod.rs | 107 ++++++++++++++----------------------
 1 file changed, 41 insertions(+), 66 deletions(-)

diff --git a/bottlecap/src/logger/mod.rs b/bottlecap/src/logger/mod.rs
index daef942a1..2b0da169f 100644
--- a/bottlecap/src/logger/mod.rs
+++ b/bottlecap/src/logger/mod.rs
@@ -31,96 +31,64 @@ fn write_json_escaped(w: &mut impl fmt::Write, s: &str) -> fmt::Result {
 #[derive(Debug, Clone, Copy)]
 pub struct Formatter;
 
-/// Visitor that captures the message and the other fields of a tracing event. Each other field
-/// becomes a JSON value, so that Datadog parses numbers as numbers.
+/// 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.
 #[derive(Default)]
 struct FieldVisitor {
     message: String,
-    /// Field names and JSON values, in the order of the event.
-    fields: Vec<(&'static str, String)>,
-}
-
-impl FieldVisitor {
-    fn push_string(&mut self, field: &tracing::field::Field, value: &str) {
-        let mut json = String::from("\"");
-        // Writing to a `String` cannot fail.
-        let _ = write_json_escaped(&mut json, value);
-        json.push('"');
-        self.fields.push((field.name(), json));
-    }
+    /// The `f64` fields, in the order of the event.
+    fields: Vec<(&'static str, f64)>,
 }
 
 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.push_string(field, &format!("{value:?}"));
         }
     }
 
     fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
         if field.name() == "message" {
             self.message = value.to_string();
-        } else {
-            self.push_string(field, value);
         }
     }
 
     fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
-        // JSON has no NaN or infinity, so write those as strings.
+        // JSON has no NaN or infinity, so drop those values.
         if value.is_finite() {
-            self.fields.push((field.name(), value.to_string()));
-        } else {
-            self.push_string(field, &value.to_string());
+            self.fields.push((field.name(), value));
         }
     }
-
-    fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
-        self.fields.push((field.name(), value.to_string()));
-    }
-
-    fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
-        self.fields.push((field.name(), value.to_string()));
-    }
-
-    fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
-        self.fields.push((field.name(), value.to_string()));
-    }
 }
 
 /// Writes `fields` as JSON members, each one preceded by a comma. A field named `group.key`
 /// goes into a nested `"group": {"key": ...}` object.
-fn write_json_fields(w: &mut impl fmt::Write, fields: &[(&'static str, String)]) -> fmt::Result {
+fn write_json_fields(w: &mut impl fmt::Write, fields: &[(&'static str, f64)]) -> fmt::Result {
     let mut written_groups: Vec<&str> = Vec::new();
     for (name, value) in fields {
-        match name.split_once('.') {
-            None => {
-                w.write_str(",\"")?;
-                write_json_escaped(w, name)?;
-                write!(w, "\":{value}")?;
-            }
-            Some((group, _)) => {
-                if written_groups.contains(&group) {
-                    continue;
-                }
-                written_groups.push(group);
-                w.write_str(",\"")?;
-                write_json_escaped(w, group)?;
-                w.write_str("\":{")?;
-                let members = fields.iter().filter_map(|(n, v)| {
-                    n.split_once('.')
-                        .filter(|(g, _)| *g == group)
-                        .map(|(_, k)| (k, v))
-                });
-                for (i, (key, value)) in members.enumerate() {
-                    w.write_str(if i == 0 { "\"" } else { ",\"" })?;
-                    write_json_escaped(w, key)?;
-                    write!(w, "\":{value}")?;
-                }
-                w.write_str("}")?;
-            }
+        let Some((group, _)) = name.split_once('.') else {
+            w.write_str(",\"")?;
+            write_json_escaped(w, name)?;
+            write!(w, "\":{value}")?;
+            continue;
+        };
+        if written_groups.contains(&group) {
+            continue;
+        }
+        written_groups.push(group);
+        w.write_str(",\"")?;
+        write_json_escaped(w, group)?;
+        w.write_str("\":{")?;
+        let members = fields
+            .iter()
+            .filter_map(|(n, v)| Some((n.strip_prefix(group)?.strip_prefix('.')?, v)));
+        for (i, (key, value)) in members.enumerate() {
+            w.write_str(if i == 0 { "\"" } else { ",\"" })?;
+            write_json_escaped(w, key)?;
+            write!(w, "\":{value}")?;
         }
+        w.write_str("}")?;
     }
     Ok(())
 }
@@ -392,16 +360,23 @@ mod tests {
     }
 
     #[test]
-    fn test_formatter_writes_flat_fields_by_type() {
+    fn test_formatter_writes_only_finite_f64_fields() {
         let output = capture_log(|| {
-            tracing::info!(count = 3_u64, ok = true, name = "a \"b\"", "fields");
+            tracing::info!(
+                ms = 1.5_f64,
+                nan = f64::NAN,
+                count = 3_u64,
+                name = "x",
+                "fields"
+            );
         });
 
         let parsed: serde_json::Value =
             serde_json::from_str(output.trim()).expect("output should be valid JSON");
 
-        assert_eq!(parsed["count"].as_u64(), Some(3));
-        assert_eq!(parsed["ok"].as_bool(), Some(true));
-        assert_eq!(parsed["name"].as_str(), Some("a \"b\""));
+        assert_eq!(parsed["ms"].as_f64(), Some(1.5));
+        assert!(parsed.get("nan").is_none());
+        assert!(parsed.get("count").is_none());
+        assert!(parsed.get("name").is_none());
     }
 }

From 75b03dbc6725f9df593df9be05ed9ea5efd7374c Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Thu, 15 Oct 2026 15:57:44 -0400
Subject: [PATCH 10/11] [SVLS-9883] Group log fields with serde_json in place
 of hand-written JSON

fields_to_json builds a serde_json::Map with a nested object for each
group, and serde_json writes the keys and numbers. A whole number is now
written as 21.0 instead of 21.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/logger/mod.rs | 47 ++++++++++++++++---------------------
 1 file changed, 20 insertions(+), 27 deletions(-)

diff --git a/bottlecap/src/logger/mod.rs b/bottlecap/src/logger/mod.rs
index 2b0da169f..177870494 100644
--- a/bottlecap/src/logger/mod.rs
+++ b/bottlecap/src/logger/mod.rs
@@ -62,35 +62,26 @@ impl tracing::field::Visit for FieldVisitor {
     }
 }
 
-/// Writes `fields` as JSON members, each one preceded by a comma. A field named `group.key`
-/// goes into a nested `"group": {"key": ...}` object.
-fn write_json_fields(w: &mut impl fmt::Write, fields: &[(&'static str, f64)]) -> fmt::Result {
-    let mut written_groups: Vec<&str> = Vec::new();
+/// Groups `fields` into JSON members. A field named `group.key` goes into a nested
+/// `"group": {"key": ...}` object.
+fn fields_to_json(fields: &[(&'static str, f64)]) -> serde_json::Map<String, serde_json::Value> {
+    let mut members = serde_json::Map::new();
     for (name, value) in fields {
-        let Some((group, _)) = name.split_once('.') else {
-            w.write_str(",\"")?;
-            write_json_escaped(w, name)?;
-            write!(w, "\":{value}")?;
-            continue;
-        };
-        if written_groups.contains(&group) {
-            continue;
-        }
-        written_groups.push(group);
-        w.write_str(",\"")?;
-        write_json_escaped(w, group)?;
-        w.write_str("\":{")?;
-        let members = fields
-            .iter()
-            .filter_map(|(n, v)| Some((n.strip_prefix(group)?.strip_prefix('.')?, v)));
-        for (i, (key, value)) in members.enumerate() {
-            w.write_str(if i == 0 { "\"" } else { ",\"" })?;
-            write_json_escaped(w, key)?;
-            write!(w, "\":{value}")?;
+        match name.split_once('.') {
+            None => {
+                members.insert((*name).to_string(), (*value).into());
+            }
+            Some((group, key)) => {
+                if let serde_json::Value::Object(group) = members
+                    .entry(group)
+                    .or_insert_with(|| serde_json::Map::new().into())
+                {
+                    group.insert(key.to_string(), (*value).into());
+                }
+            }
         }
-        w.write_str("}")?;
     }
-    Ok(())
+    members
 }
 
 impl<S, N> FormatEvent<S, N> for Formatter
@@ -135,7 +126,9 @@ where
         write!(writer, "{{\"status\":\"{level}\",\"message\":\"")?;
         write_json_escaped(&mut writer, &message)?;
         writer.write_char('"')?;
-        write_json_fields(&mut writer, &visitor.fields)?;
+        for (key, value) in fields_to_json(&visitor.fields) {
+            write!(writer, ",{}:{value}", serde_json::Value::from(key))?;
+        }
         writeln!(writer, "}}")
     }
 }

From f0fcf610f300104e5bfeedb97f4197b6a053979d Mon Sep 17 00:00:00 2001
From: lym953 <10097700+lym953@users.noreply.github.com>
Date: Thu, 15 Oct 2026 19:03:41 -0400
Subject: [PATCH 11/11] [SVLS-9883] Log the AppSec and endpoint secret
 durations only when used

create_appsec_processor_ms is set only when AppSec is enabled, and
resolve_additional_endpoint_secrets_ms only when the config has an
additional endpoints secret ARN. Otherwise the fields are left out of
the summary line, so that a 0.0 does not lower the average of the
functions that use the feature, and the field shows that it was on.

has_additional_endpoints_secrets() holds the check that
resolve_additional_endpoints_secrets() used for its early return, so that
main.rs and that function share it.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 bottlecap/src/bin/bottlecap/main.rs | 20 ++++++++++++++------
 bottlecap/src/logger/cold_start.rs  | 10 ++++++----
 bottlecap/src/secrets/decrypt.rs    | 27 +++++++++++++++++++++------
 3 files changed, 41 insertions(+), 16 deletions(-)

diff --git a/bottlecap/src/bin/bottlecap/main.rs b/bottlecap/src/bin/bottlecap/main.rs
index 6471cded7..3078b25b6 100644
--- a/bottlecap/src/bin/bottlecap/main.rs
+++ b/bottlecap/src/bin/bottlecap/main.rs
@@ -83,7 +83,9 @@ use bottlecap::{
     },
 };
 use datadog_fips::reqwest_adapter::create_reqwest_client_builder;
-use decrypt::{resolve_additional_endpoints_secrets, resolve_secrets};
+use decrypt::{
+    has_additional_endpoints_secrets, resolve_additional_endpoints_secrets, resolve_secrets,
+};
 use dogstatsd::{
     aggregator::{
         AggregatorHandle as MetricsAggregatorHandle, AggregatorService as MetricsAggregatorService,
@@ -172,9 +174,12 @@ async fn main() -> anyhow::Result<()> {
     let step_start_time = Instant::now();
     let mut lambda_config = config::get_config(Path::new(&lambda_directory));
     cold_start_durations.load_config_ms = elapsed_ms(step_start_time);
-    let step_start_time = Instant::now();
-    resolve_additional_endpoints_secrets(&mut lambda_config, &aws_config).await;
-    cold_start_durations.resolve_additional_endpoint_secrets_ms = elapsed_ms(step_start_time);
+    if has_additional_endpoints_secrets(&lambda_config) {
+        let step_start_time = Instant::now();
+        resolve_additional_endpoints_secrets(&mut lambda_config, &aws_config).await;
+        cold_start_durations.resolve_additional_endpoint_secrets_ms =
+            Some(elapsed_ms(step_start_time));
+    }
     let config = Arc::new(lambda_config);
 
     // Build one shared reqwest::Client for metrics, logs, trace proxy flushing, and calls to
@@ -427,16 +432,19 @@ async fn extension_loop_active(
     // AppSec processor (if enabled)
     let step_start_time = Instant::now();
     let appsec_processor = match AppSecProcessor::new(config) {
-        Ok(p) => Some(Arc::new(TokioMutex::new(p))),
+        Ok(p) => {
+            cold_start_durations.create_appsec_processor_ms = Some(elapsed_ms(step_start_time));
+            Some(Arc::new(TokioMutex::new(p)))
+        }
         Err(AppSecFeatureDisabled) => None,
         Err(e) => {
+            cold_start_durations.create_appsec_processor_ms = Some(elapsed_ms(step_start_time));
             error!(
                 "AAP | error creating App & API Protection processor, the feature will be disabled: {e}"
             );
             None
         }
     };
-    cold_start_durations.create_appsec_processor_ms = elapsed_ms(step_start_time);
 
     let (
         trace_agent_channel,
diff --git a/bottlecap/src/logger/cold_start.rs b/bottlecap/src/logger/cold_start.rs
index a917787c1..c80228d91 100644
--- a/bottlecap/src/logger/cold_start.rs
+++ b/bottlecap/src/logger/cold_start.rs
@@ -13,10 +13,12 @@ pub struct ColdStartDurations {
     pub create_extensions_api_client_ms: f64,
     pub register_extension_ms: f64,
     pub load_config_ms: f64,
-    pub resolve_additional_endpoint_secrets_ms: f64,
+    /// Set only when the config has an additional endpoints secret ARN.
+    pub resolve_additional_endpoint_secrets_ms: Option<f64>,
     pub wait_for_register_ms: f64,
     pub start_dogstatsd_ms: f64,
-    pub create_appsec_processor_ms: f64,
+    /// Set only when App and API Protection is enabled.
+    pub create_appsec_processor_ms: Option<f64>,
     pub start_telemetry_listener_ms: f64,
 }
 
@@ -30,10 +32,10 @@ impl ColdStartDurations {
             create_extensions_api_client_ms: 0.0,
             register_extension_ms: 0.0,
             load_config_ms: 0.0,
-            resolve_additional_endpoint_secrets_ms: 0.0,
+            resolve_additional_endpoint_secrets_ms: None,
             wait_for_register_ms: 0.0,
             start_dogstatsd_ms: 0.0,
-            create_appsec_processor_ms: 0.0,
+            create_appsec_processor_ms: None,
             start_telemetry_listener_ms: 0.0,
         }
     }
diff --git a/bottlecap/src/secrets/decrypt.rs b/bottlecap/src/secrets/decrypt.rs
index faebd4d4b..1cbeee037 100644
--- a/bottlecap/src/secrets/decrypt.rs
+++ b/bottlecap/src/secrets/decrypt.rs
@@ -121,6 +121,17 @@ fn build_direct_aws_client() -> Option<Client> {
 /// documented.
 const ADDITIONAL_ENDPOINTS_SECRET_FETCH_TIMEOUT: Duration = Duration::from_secs(5);
 
+/// Whether `config` sets any `DD_*_ADDITIONAL_ENDPOINTS_SECRET_ARN`, so that
+/// [`resolve_additional_endpoints_secrets`] has secrets to fetch.
+#[must_use]
+pub fn has_additional_endpoints_secrets(config: &Config) -> bool {
+    !(config.additional_endpoints_secret_arn.is_empty()
+        && config.apm_additional_endpoints_secret_arn.is_empty()
+        && config
+            .logs_config_additional_endpoints_secret_arn
+            .is_empty())
+}
+
 /// Resolves the `DD_*_ADDITIONAL_ENDPOINTS_SECRET_ARN` dual-shipping secrets into `config`.
 ///
 /// Each secret holds the whole additional-endpoints JSON blob, in the same shape as the
@@ -131,12 +142,7 @@ pub async fn resolve_additional_endpoints_secrets(
     config: &mut Config,
     aws_config: &Arc<AwsConfig>,
 ) {
-    if config.additional_endpoints_secret_arn.is_empty()
-        && config.apm_additional_endpoints_secret_arn.is_empty()
-        && config
-            .logs_config_additional_endpoints_secret_arn
-            .is_empty()
-    {
+    if !has_additional_endpoints_secrets(config) {
         return;
     }
 
@@ -650,6 +656,15 @@ mod tests {
         assert_eq!(result, raw);
     }
 
+    #[test]
+    fn test_has_additional_endpoints_secrets() {
+        let mut config = Config::default();
+        assert!(!has_additional_endpoints_secrets(&config));
+        config.logs_config_additional_endpoints_secret_arn =
+            "arn:aws:secretsmanager:us-east-1:123456789012:secret:x".to_string();
+        assert!(has_additional_endpoints_secrets(&config));
+    }
+
     #[tokio::test]
     async fn test_resolve_additional_endpoints_secrets_noop_when_no_arns_set() {
         let mut config = Config::default();