Repository navigation
Conversation
❌ ErrorsYour PR has failed checks. Please review the issues below and take necessary action before merging. 🚦 1 Pipeline job failed
Useful? React with 👍 / 👎 This comment will be updated automatically if new data arrives.🔗 Commit SHA: 62a8bf7 | Docs | View more details | Give us feedback! |
9862713 to
24a9990
Compare
lym953
changed the title
|
Changing back to draft. Will make the change in serverless-components and make |
lym953
changed the title
|
Publishing this again since the |
There was a problem hiding this comment.
🟡 Changes recommended
The bundled wrapper does not support directive lists, and the dependencies remain pinned to a temporary upstream revision.
2 open findings
What changed in this PR
Adds target-specific DD_LOG_LEVEL filtering while preserving default logging behavior.
Changes:
- Parses comma-separated
tracingfilter directives and reports invalid entries. - Adds unit coverage for filtering behavior.
- Updates
serverless-componentsdependencies.
| File | Description |
|---|---|
bottlecap/src/logger.rs |
Documents the cold-start logging target. |
bottlecap/src/bin/bottlecap/main.rs |
Implements and tests directive-based filtering. |
bottlecap/Cargo.toml |
Updates shared component revisions. |
bottlecap/Cargo.lock |
Locks the updated revisions. |
🧠 Review effort: Balanced
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
lym953
changed the title
|
Converting to draft again. Will move the helper function to a crate in |
776fb27 to
acf98dd
Compare
4a71d02 to
e47df3c
Compare
clifordshelton
left a comment
clifordshelton
left a comment
There was a problem hiding this comment.
Thanks for moving the filter logic into a shared crate. Keeping it out of DD_LOG_LEVEL makes sense too, since the tracers and libraries also read that variable. I have two inline comments and two broader ones here.
1. Decide whether DD_LOG_LEVEL_BY_TARGET is for customers or for us
This adds a new environment variable that customers can set, but it isn't documented anywhere they'd see it. The README in serverless-components#180 is written for developers. Before we document it, it's worth noticing what the setting depends on. Besides custom targets like cold_start_duration, it accepts our internal Rust module paths, like bottlecap::traces, and crate names with underscores. Those can change any time we move or rename code. If customers start using them, a refactor on our side would quietly change what their setting does, and nobody would notice.
My suggestion is to treat it as a support and debugging tool for now. Only document the custom targets we add on purpose (cold_start_duration, and later ones like trace_flush_duration), since those are names we can keep stable. Module paths still work, but we don't promote them. That way we can add or rename modules without breaking anyone. It would be good to confirm this with the team before merging, since the name and behavior are hard to change once customers rely on them.
2. Bring back the note about target names
An entry matches every target that starts with its text, so trace_flush=debug would also turn on trace_flush_duration. There was a code comment warning about this, but the "Drop the DD_LOG_LEVEL_BY_TARGET notes" commit removed it, and now it's only in the serverless-components README. Whoever adds the next target will be working in logger.rs, not reading that README. It's better to put the note back next to COLD_START_DURATION in logger.rs, so new target names don't accidentally start with an existing one.
| let env_filter = format!( | ||
| "h2=off,hyper=off,reqwest=off,rustls=off,datadog-trace-mini-agent=off,{log_level:?}", | ||
| ); | ||
| let (env_filter, invalid_entries) = build_env_filter( |
There was a problem hiding this comment.
The base filter turns off h2, hyper, reqwest and rustls for a reason, and with this change a DD_LOG_LEVEL_BY_TARGET entry can turn them back on. The extension reads its own stdout and sends it to Datadog as logs (see the "Be careful adding logs inside the logs pipeline" note in AGENTS.md). These HTTP crates log on every request, and that includes the requests the extension makes to send logs. So with hyper=debug, every flush creates more log lines, which get sent in the next flush, which creates more lines, and so on. That adds a lot of noise to the customer's CloudWatch and Datadog logs, and it costs them money.
Since this is an environment variable customers can set, I'd keep those four crates locked to off. You can skip any entry for them and add it to invalid_entries, so the user gets the same warning as for a typo. The cleanest place for this is probably the crate in serverless-components#180, for example by letting the caller pass a list of targets that can't be changed. That would mean making the change before #180 merges. The overrides_base_filter test that sets h2=debug would then change to check that the entry is rejected.
There was a problem hiding this comment.
Sometimes, we do want to turn on logging for them to debug network issues, for example, in SLES-3059. To avoid infinite loop, for logs from these modules, we can make them appear only in CloudWatch logs and don't send them to Datadog. I'm doing this in #1429
There was a problem hiding this comment.
Addressed in #1429. Sometimes we do need these logs to debug network issues. That PR allows making them appear only in CloudWatch Logs but not Datadog to avoid infinite loops.
fcb610e to
39357e3
Compare
## Problem
The extension's cold start duration increases from time to time, and finding the cause takes a lot of engineering time. The extension logs only the total time to ready. So, to find which step became slower, we must add temporary timers and build a test layer.
## This PR
At the end of each cold start, the extension logs one debug line with the duration of each initialization step. The durations are JSON numbers in milliseconds, rounded to 2 decimals, under a `cold_start` object. Datadog parses them as numbers, so each step can go on a chart, or into a filter such as `@cold_start.start_telemetry_listener_ms:>50`. Two fields appear only when their feature is on, as described below. A real line from the test below, with AppSec off, shown here on several lines. The extension writes it as one line.
```json
{
"status": "DEBUG",
"message": "DD_EXTENSION | DEBUG | Cold start step durations",
"cold_start": {
"total_ms": 55.46,
"enable_logging_ms": 7.7,
"load_aws_config_ms": 1.25,
"create_extensions_api_client_ms": 0.86,
"register_extension_ms": 4.71,
"load_config_ms": 3.79,
"wait_for_register_ms": 0.87,
"start_dogstatsd_ms": 0.92,
"start_telemetry_listener_ms": 39.52
}
}
```
The line uses the tracing target `cold_start_duration`, so that #1413 can turn it on alone, without the other debug logs. The existing "Datadog Next-Gen Extension ready in Nms" line stays as it is, on the default target.
The changes in the code:
- `main.rs` records each step's duration into a struct, `ColdStartDurations`, which is in the new file `logger/cold_start.rs`.
- The extension's log formatter, which wrote only the message, also writes the `f64` fields of a log event as JSON numbers. A field named `cold_start.x` goes into the nested `cold_start` object. Fields of other types are dropped, as before.
- `logger.rs` moves to `logger/mod.rs`, so that the extension's logging code is in one folder.
### Which steps get a field
To select the steps, I made a probe build with a timer on every initialization step. Then I ran five cold starts with it. This PR keeps these steps:
- Each step that took more than 0.1 ms in one or more runs.
- Two steps that took less than 0.1 ms in the test, but do slow work when a feature is on. Their fields appear only when the feature is on, so that a 0.0 does not lower the average of the functions that use the feature:
- `resolve_additional_endpoint_secrets_ms`: resolving additional endpoint secrets. It calls AWS when an additional endpoints secret ARN (Amazon Resource Name) is set, for example `DD_ADDITIONAL_ENDPOINTS_SECRET_ARN`.
- `create_appsec_processor_ms`: creating the AppSec processor. It builds the WAF (web application firewall) when AppSec is on.
The probe build also timed the steps that follow. Each one took less than 0.1 ms in all five runs, so this PR has no field for them:
- Creating the shared HTTP client
- Setting up tags
- Starting the logs agent
- Starting the invocation processor
- Starting the trace agent
- Starting the Runtime API proxy
- Starting the lifecycle listener
- Starting the OTLP agent
Each step has its own timer, so the step durations do not add up to the total. For example, the registration request runs in a background task at the same time as config loading. `wait_for_register_ms` is the time that the main task waits for it.
## Testing
I built an arm64 layer of commit `f0fcf610` and deployed it on a Python 3.13 arm64 function with `DD_LOG_LEVEL=debug`. I forced two cold starts with AppSec off, and two with `DD_SERVERLESS_APPSEC_ENABLED=true`. Then I read the extension's logs in CloudWatch.
Each cold start logged one "Cold start step durations" line and one "ready in" line, and no per-step lines. The durations in milliseconds:
| Field | AppSec off, cold start 1 | AppSec off, cold start 2 | AppSec on, cold start 3 | AppSec on, cold start 4 |
| --- | --- | --- | --- | --- |
| `total_ms` | 55.46 | 57.36 | 77.89 | 72.79 |
| `enable_logging_ms` | 7.7 | 7.02 | 7.3 | 7.14 |
| `load_aws_config_ms` | 1.25 | 1.16 | 1.18 | 4.87 |
| `create_extensions_api_client_ms` | 0.86 | 7.7 | 0.87 | 0.87 |
| `register_extension_ms` | 4.71 | 4.22 | 9.31 | 4.21 |
| `load_config_ms` | 3.79 | 1.72 | 7.03 | 1.64 |
| `wait_for_register_ms` | 0.87 | 2.87 | 2.28 | 2.59 |
| `start_dogstatsd_ms` | 0.92 | 0.41 | 0.28 | 0.32 |
| `create_appsec_processor_ms` | not in the line | not in the line | 41.09 | 40.25 |
| `start_telemetry_listener_ms` | 39.52 | 36.03 | 17.47 | 14.7 |
`create_appsec_processor_ms` is in the line only when AppSec is on. `resolve_additional_endpoint_secrets_ms` is in none of the lines, because the test function has no additional endpoint secrets. A unit test checks the condition for that field, but I did not test that path on Lambda. I did not test on amd64 or FIPS builds.
## Next steps:
1. Add logging for other things, such as log/trace/metric flushing duration.
2. Support using an env var to configure which log groups are on
🤖 Generated with [Claude Code](https://claude.com/claude-code)
Co-authored-by: yiming.luo <yiming.luo@datadoghq.com>
DD_LOG_LEVEL_BY_TARGET is a comma-separated list of `<target>=<level>` entries, such as `cold_start_duration=debug`. Each entry sets the log level of one tracing target, and DD_LOG_LEVEL stays the level of all other targets. The parsing is in datadog-serverless-logging, from serverless-components. The extension logs a warning for each entry that is not valid. The HTTP libraries h2, hyper, reqwest and rustls stay off, and an entry cannot turn them on. The extension sends its own logs to Datadog, so their logs for each request would add lines to each flush. One list, LOCKED_LOG_TARGETS, builds both their `off` rules and the locked list. The serverless-components dependencies point at the head of DataDog/serverless-components#183, which adds the locked targets. This commit replaces the earlier commits of this PR, rebuilt on top of the current #1412. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
39357e3 to
94d83cf
Compare
…logs Drop the lock on h2, hyper, reqwest and rustls. The lock kept their lines out of the logs that the extension sends to Datadog, because those libraries log each log upload too. #1429 keeps their lines out of the upload instead, so this commit must merge after #1429. The four libraries stay off by default. serverless-components goes back to main (19270f5), which has no lock argument. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
I think it's mostly for us to help customers with support tickets, though customers are not disallowed to set this themselves. For now I'd just add documentation of it in this repo, without mentioning it in Datadog's doc site.
Now that these logs only appear in CloudWatch logs, the cost will be lower. And if the customer turns them on intentionally, they probably have some network issues to debug, and the cost shouldn't be a big concern. |
The setting is mainly for Datadog engineers and support, so it is documented next to the logger code and not on the Datadog documentation site. The README says which target names we keep stable, and how to find where an upload to Datadog stops with the HTTP library logs. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
|
Addressed all the comments. Publishing again. |
There was a problem hiding this comment.
🟡 Changes recommended
The snapshot enables HTTP-target overrides without prerequisite #1429’s safeguards against log-upload feedback.
1 open finding
1 resolved since last review
🧠 Review effort: Balanced
| let (env_filter, invalid_entries) = build_env_filter( | ||
| &format!( | ||
| "h2=off,hyper=off,reqwest=off,rustls=off,datadog-trace-mini-agent=off,{log_level:?}" | ||
| ), | ||
| &std::env::var(LEVEL_BY_TARGET_ENV_VAR).unwrap_or_default(), |
Keep the setting, its format and the name stability rule. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
The new variable is parsed by the crate
datadog-serverless-logging, from DataDog/serverless-components#180. #1429 is stacked on this PR. Merge this PR first and #1429 right after it. This PR lets an entry turn the HTTP libraries on, and #1429 keeps their lines out of the logs that the extension sends to Datadog.Problem
DD_LOG_LEVEL=debugturns on debug logs from all parts of the extension. In a test, three cold starts at debug level logged 117 debug lines, when only 33 of them were cold start durations. Too many logs can be noisy for users (either customers or Datadog engineers) who just want to debug cold starts.This PR
This PR adds
DD_LOG_LEVEL_BY_TARGET, a comma-separated list of<target>=<level>entries. Each entry sets the log level of one tracing target, andDD_LOG_LEVELstays the level of all other targets. Both are environment variables of the Lambda function. For example:DD_LOG_LEVELinfoDD_LOG_LEVEL_BY_TARGETcold_start_duration=debug,dogstatsd=debugSuppose there are logging statements with target
cold_start_duration, like:Then here are some examples (each row is one scenario):
DD_LOG_LEVELDD_LOG_LEVEL_BY_TARGETinfocold_start_duration=debugdebugcold_start_duration=offinfodogstatsd=debugdogstatsdcrate ofserverless-componentscold_start_duration=debugA target can be a custom target that the logging statement sets, a module path such as
bottlecap::traces, or a crate name such asdogstatsd. An entry matches every target that starts with its text. The README ofdatadog-serverless-logginglists all the kinds of targets.The extension logs a warning for an entry that is not valid, and skips it. Examples are a level with no target such as
debug, which would otherwise replaceDD_LOG_LEVEL, and an unknown level such ascold_start_duration=verbose.The HTTP libraries
h2,hyper,reqwestandrustlsstay off by default, and an entry can turn them on. For example,hyper_util=debug,h2=debugshows each TCP connect and each HTTP/2 frame of the flushes to Datadog, which shows where a stalled flush stops. These lines go to CloudWatch Logs only. The extension does not send them to Datadog (#1429), because these libraries log each HTTP request, including the requests that send logs.The README in the logger folder (
bottlecap/src/logger/README.md) documents the setting for Datadog engineers and support, and lists the target names that we keep stable. The Datadog documentation site does not describe it.Why not
DD_LOG_LEVELThe Datadog libraries and tracers in the function also read
DD_LOG_LEVEL, and they accept only a plain level. For example,datadog-lambda-pythonlogs "Invalid log level" for any other value, anddd-trace-rslogs a parse error. Support for<target>=<level>entries inDD_LOG_LEVELwould need changes in several repositories. These include tracers such asdd-trace-javaanddd-trace-dotnet, which Serverless teams do not own and which run in many environments other than Lambda.Testing
I built an arm64 layer of commit
39357e3f. It has the same change as the current commit, which is rebased ontomainafter #1412 merged. I deployed it on a Python 3.13 arm64 function. For each row, I forced 2 cold starts and counted the extension's log lines in CloudWatch.DD_LOG_LEVELDD_LOG_LEVEL_BY_TARGETinfocold_start_duration=debuginfohyper=debug,h=debug,cold_start_duration=debugdebugcold_start_duration=offinfodogstatsd=debug,cold_start_duration=verboseIgnoring invalid DD_LOG_LEVEL_BY_TARGET entries: ["hyper=debug", "h=debug"], and nohyperlogs appeared. This row tested the lock on the HTTP libraries, which commit9b19382aremoves. See the next section.Ignoring invalid DD_LOG_LEVEL_BY_TARGET entries: ["cold_start_duration=verbose"]. All 10 debug lines are five messages from thedogstatsdcrate, once for each cold start, for example "DogStatsD using default SO_RCVBUF".I did not test on amd64 or FIPS builds.
HTTP library entries, after the lock removal
I built an amd64 layer from this PR together with #1429, and deployed it on Python 3.13 functions with
DD_LOG_LEVEL=debugandDD_LOG_LEVEL_BY_TARGET=hyper_util=debug,h2=debug.hyper_utillines in CloudWatch Logsconnecting to <ip>:<port>,connected to <ip>:<port>and connection pool linesh2lines in CloudWatch Logssend frame=Headers { … },received frame=Headers { … }and other frames🤖 Generated with Claude Code