Skip to content

fix(logging): remove duplicate request_id field in request lifecycle logs#8307

Open
sengopal wants to merge 5 commits into
mainfrom
fix/push-handler-request-log-level
Open

fix(logging): remove duplicate request_id field in request lifecycle logs#8307
sengopal wants to merge 5 commits into
mainfrom
fix/push-handler-request-log-level

Conversation

@sengopal
Copy link
Copy Markdown

@sengopal sengopal commented Apr 17, 2026

Summary

Fixes duplicate request_id appearing twice on every request received / request completed log line in the worker.

The handle_payload span already carries request_id as a span field (along with component, endpoint, namespace, instance_id). The explicit request_id = %rid argument in the info! calls caused the field to be emitted a second time — once as a bare unquoted value (event field) and once as a quoted string (span field).

Before (raw log from original report — request_id duplicated on every line):

2026-04-15T08:33:31.214177Z  INFO handle_payload: dynamo_runtime::pipeline::network::ingress::push_handler: request received request_id=66a9b5c7-2978-40f1-bee0-a0b2e85c10fb request_id="66a9b5c7-2978-40f1-bee0-a0b2e85c10fb" component="backend" endpoint="generate" namespace="dynamo" instance_id=7587894189871522064
2026-04-15T08:33:31.219612Z  INFO handle_payload: dynamo_runtime::pipeline::network::ingress::push_handler: request received request_id=9cb1c4a3-82a7-4f93-aaf6-af06f11007f5 request_id="9cb1c4a3-82a7-4f93-aaf6-af06f11007f5" component="backend" endpoint="generate" namespace="dynamo" instance_id=7587894189871522064

After (captured on this PR with Qwen3-0.6B / SGLang — request_id once, from span):

2026-04-17T17:30:33.444856Z  INFO handle_payload: dynamo_runtime::pipeline::network::ingress::push_handler: request received request_id="ddd76dbd-8158-4c88-8457-689bf86cc86e" component="backend" endpoint="generate" namespace="dynamo" instance_id=11407193840597806990
2026-04-17T17:30:40.247600Z  INFO handle_payload: dynamo_runtime::pipeline::network::ingress::push_handler: request completed request_id="ddd76dbd-8158-4c88-8457-689bf86cc86e" component="backend" endpoint="generate" namespace="dynamo" instance_id=11407193840597806990

Changes

lib/runtime/src/pipeline/network/ingress/push_handler.rs

  • Drop explicit request_id field from "request received" and "request completed" info! calls — the span provides it

Test plan

  • Run sglang stack and confirm request_id appears only once per lifecycle log line
  • Confirm component, endpoint, namespace, instance_id still present in output via span context

🤖 Generated with Claude Code

"request received" and "request completed" fire on every inbound
request, producing excessive log noise at default log levels. Debug
is the correct level for per-request chatter; info should be reserved
for meaningful state changes.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
@sengopal sengopal requested a review from a team as a code owner April 17, 2026 16:40
@copy-pr-bot
Copy link
Copy Markdown

copy-pr-bot Bot commented Apr 17, 2026

This pull request requires additional validation before any workflows can run on NVIDIA's runners.

Pull request vetters can view their responsibilities here.

Contributors can view more details about this message here.

@github-actions github-actions Bot added the fix label Apr 17, 2026
Copy link
Copy Markdown
Contributor

@devin-ai-integration devin-ai-integration Bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

✅ Devin Review: No Issues Found

Devin Review analyzed this PR and found no potential bugs to report.

View in Devin Review to see 1 additional finding.

Open in Devin Review

@coderabbitai
Copy link
Copy Markdown
Contributor

coderabbitai Bot commented Apr 17, 2026

Walkthrough

Two logging statements in the request lifecycle handler are downgraded from info! to debug! level. The changes affect request receipt during initialization and request completion via RAII guard drop. No logic, control flow, or error handling modifications are present.

Changes

Cohort / File(s) Summary
Logging Level Downgrade
lib/runtime/src/pipeline/network/ingress/push_handler.rs
Downgrade two tracing::info! calls to tracing::debug! for request lifecycle events tied to request_id: one at request receipt and one at RequestMetricsGuard drop. No impact on metrics collection or control flow.

Estimated code review effort

🎯 1 (Trivial) | ⏱️ ~3 minutes

🚥 Pre-merge checks | ❌ 3

❌ Failed checks (2 warnings, 1 inconclusive)

Check name Status Explanation Resolution
Docstring Coverage ⚠️ Warning Docstring coverage is 0.00% which is insufficient. The required threshold is 80.00%. Write docstrings for the functions missing them to satisfy the coverage threshold.
Title check ⚠️ Warning The title describes removing duplicate request_id field in logs, but the actual change downgrades log levels from info to debug—these are distinct issues. Update the title to reflect the primary change: 'fix(logging): downgrade request lifecycle logs from info to debug' or similar.
Description check ❓ Inconclusive The description thoroughly explains the duplicate request_id issue with before/after examples, but the PR objectives indicate the actual change is downgrading log levels, not removing the request_id field. Clarify whether the PR removes the duplicate request_id field or downgrades log levels—the description and objectives describe different changes.

✏️ Tip: You can configure your own custom pre-merge checks in the settings.


Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands and usage tips.

The handle_payload span already carries request_id, component, endpoint,
namespace, and instance_id. Explicitly repeating request_id in the info!
call caused it to appear twice in log output. Drop the redundant field
so all structured context comes from the span once.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
Copy link
Copy Markdown
Contributor

@devin-ai-integration devin-ai-integration Bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Devin Review found 2 new potential issues.

View 2 additional findings in Devin Review.

Open in Devin Review

if let Some(request_id) = &self.request_id {
tracing::info!(request_id = %request_id, "request completed");
if self.request_id.is_some() {
tracing::info!("request completed");
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Log level accidentally reverted from debug to info in Drop impl

The immediately preceding commit (2af9c9aa6e) deliberately downgraded these per-request lifecycle logs from info to debug (commit message: "fix(runtime): downgrade per-request lifecycle logs from info to debug"). This commit, which only intends to remove the duplicate request_id field, accidentally changes tracing::debug! back to tracing::info!. In production with high request volume, this will cause excessive logging at the info level — exactly the problem the previous commit fixed.

Suggested change
tracing::info!("request completed");
tracing::debug!("request completed");
Open in Devin Review

Was this helpful? React with 👍 or 👎 to provide feedback.

if let Some(rid) = &request_id {
tracing::info!(request_id = %rid, "request received");
if request_id.is_some() {
tracing::info!("request received");
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Log level accidentally reverted from debug to info in handle_payload

Same issue as in the Drop impl: the previous commit (2af9c9aa6e) deliberately downgraded this log from info to debug, and this commit accidentally reverts it back to info while removing the request_id field. This will produce a noisy info-level "request received" log for every incoming request.

Suggested change
tracing::info!("request received");
tracing::debug!("request received");
Open in Devin Review

Was this helpful? React with 👍 or 👎 to provide feedback.

@nnshah1
Copy link
Copy Markdown
Contributor

nnshah1 commented Apr 17, 2026

question: is the intent here to remove duplicate fields or change level ?

If change level - then we should have a discussion as we purposefully wanted to have these at info level - perhaps its info level at the frontend and debug at the worker - but we should come up with a general guidance.

@sengopal sengopal changed the title fix(runtime): downgrade per-request lifecycle logs from info to debug fix(runtime): Fix formatting of per-request lifecycle logs Apr 17, 2026
@sengopal sengopal changed the title fix(runtime): Fix formatting of per-request lifecycle logs fix(logging): remove duplicate request_id field in request lifecycle logs Apr 17, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants