otelcol/grpclog: suppress benign gRPC client-disconnect warnings - #15024
Conversation
|
recheck |
|
/easycla |
20d0b54 to
665e053
Compare
|
/easycla |
|
This feels like a bit of a heavy-handed solution. grpc-go already has a verbosity check for these kinds of errors, e.g. see https://github.com/grpc/grpc-go/blob/d574bad188f25ba03d41a506e6f2ef93837ad10b/internal/transport/http2_server.go#L642 The zapgrpc implementation of the e.g. verbosity level 2 is being mapped to error level, which is nonsense for two reasons: error level logs should be less verbose than info, not more; grpc-go's verbosity is meant to be independent of the primary logger level. So either we fix that upstream, or wrap the zapgrpc logger. |
grpc-go gates chatty per-RPC messages — including transport notices logged on normal client disconnect — behind LoggerV2.V(2). zapgrpc's V is implemented as levelEnabler.Enabled(level-1), conflating grpclog verbosity with zap severity: with WARN enabled, V(2) returns true and the messages emit at WARN as alarming "HandleStreams failed to read frame: connection reset by peer" entries. Wrap the installed grpclog.LoggerV2 with a corrected V() that compares against a fixed verbosity threshold (default 0). Verbose messages now stop at grpc-go before formatting, instead of being filtered out of the log stream. Severity-level emission is unchanged. Fixes open-telemetry#5169 See uber-go/zap#1544
b88740e to
b37adb8
Compare
|
@axw thanks for the pointer to uber-go/zap#1544 — that crystallized it. Pushed a redesign that wraps the grpclog.LoggerV2 with a corrected V() instead of filtering log output. The chatty V(2)-gated transport messages now stop at grpc-go before formatting, rather than being string-matched out of the formatted stream. Severity-level emission is unaffected. PTAL when you have a moment. |
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #15024 +/- ##
=======================================
Coverage 91.13% 91.13%
=======================================
Files 701 701
Lines 45745 45783 +38
=======================================
+ Hits 41689 41724 +35
- Misses 2843 2845 +2
- Partials 1213 1214 +1 ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
|
@kruthiwusirika5 code looks good, thanks. Please create a changelog entry ( |
|
@axw chloggen entry added in 008f6cd1f — bug_fix against pkg/otelcol, links #5169 and explains the underlying uber-go/zap#1544 for context. make chlog-validate passes locally. Workflows on the new commit are sitting in action_required (first-time contributor gate) — could you trigger them? The previously-failing changelog check should flip green once it re-runs against this SHA. @open-telemetry/collector-approvers — this PR is now ready for a final pass. Code redesign was acked by @axw two days ago; just the changelog entry was outstanding. |
The new chloggen entry references three identifiers that the cspell dictionary does not yet contain: grpclog, grpclog's, and zapgrpc. With strict mode enabled the spell-check job fails on these unknown words. Add the three terms in alphabetical order; they match the existing convention of including both the bare and the possessive form (cf. kafkaexporter / kafkaexporter's, mdatagen / mdatagen's). The pre-existing "lifecycles" warnings against CHANGELOG.md and CHANGELOG-API.md are not addressed here — they fail on main as well and are outside the scope of this change. Signed-off-by: Sai Kruthi Wusirika <kruthiwusirika@gmail.com>
|
@axw spell-check fix pushed in 6b4fa6d34 — added The two pre-existing Workflows on the new commit are sitting in |
Merging this PR will not alter performance
|
The cspell-action runs with strict=true and incremental_files_only=false, so it fails the build on any unknown word anywhere in the repo, including files this PR does not touch. The chloggen entry added in this branch is clean (grpclog/zapgrpc were addressed in 6b4fa6d), but the run still fails on a pre-existing 'lifecycles' usage in CHANGELOG.md and CHANGELOG-API.md that has been failing on main for several consecutive runs. Adding the missing word to the dictionary so this PR's CI can converge without waiting for a separate main-fix PR. The token is unambiguously correct English; the omission is a dictionary gap, not a misspelling. Signed-off-by: Sai Kruthi Wusirika <kruthiwusirika@gmail.com>
|
@axw the spell-check rerun on |
|
Thank you for your contribution @kruthiwusirika5! 🎉 We would like to hear from you about your experience contributing to OpenTelemetry by taking a few minutes to fill out this survey. |
…n-telemetry#15024) Fixes open-telemetry#5169 ## Problem When a gRPC client disconnects normally (e.g., a .NET app shutting down its `TracerProvider`), the collector logs spurious WARN messages from the gRPC transport layer: These are expected during graceful client shutdown but appear alarming to operators and pollute production logs. ## Root cause grpc-go is doing the right thing: messages like this are gated behind `LoggerV2.V(2)` in `internal/transport/http2_server.go`, i.e. they are explicitly classified as supplemental verbosity, not severity-level warnings. They should never reach a WARN sink. The bug is in zapgrpc. `zapgrpc.Logger.V` is implemented as `levelEnabler.Enabled(zapcore.Level(level - 1))`, which conflates grpclog's *verbosity* with zap's *severity*. With WARN enabled, `V(2)` returns true, so grpc-go thinks verbosity level 2 is permitted and emits the message — which then gets formatted by zapgrpc as a WARN entry. See [uber-go/zap#1544](uber-go/zap#1544). ## Solution Wrap the installed `grpclog.LoggerV2` with a `fixedVerbosityLogger` whose `V()` compares the requested level against a fixed threshold (default 0) instead of the underlying zap severity enabler. This restores grpclog's intended verbosity gating, so verbose messages stop at grpc-go before formatting rather than being filtered out of the log stream after the fact. The default threshold of `0` matches grpclog when `GRPC_GO_LOG_VERBOSITY_LEVEL` is unset. This approach: - Addresses the root cause (broken `V()` mapping) rather than string-matching specific message contents. - Stops chatty messages at the source, before grpc-go formats them. - Is generic — kills *all* `V(2)+` noise, including future grpc-go additions, not just two cherry-picked patterns. - Leaves severity-level emission (`Info` / `Warning` / `Error`) completely unchanged. - Tiny: ~10 lines of wrapper plus comment. ## Testing - `TestFixedVerbosity` — asserts `V(0)` is enabled and `V(1)`/`V(2)` are not at the default threshold. - `TestSeverityLevelsUnaffected` — direct `Warning("…")` still fires at WARN, confirming the wrapper does not gate severity. - Existing `TestGRPCLogger` cases continue to pass unchanged. --------- Signed-off-by: Sai Kruthi Wusirika <kruthiwusirika@gmail.com>
Fixes #5169
Problem
When a gRPC client disconnects normally (e.g., a .NET app shutting
down its
TracerProvider), the collector logs spurious WARN messagesfrom the gRPC transport layer:
These are expected during graceful client shutdown but appear
alarming to operators and pollute production logs.
Root cause
grpc-go is doing the right thing: messages like this are gated
behind
LoggerV2.V(2)ininternal/transport/http2_server.go,i.e. they are explicitly classified as supplemental verbosity, not
severity-level warnings. They should never reach a WARN sink.
The bug is in zapgrpc.
zapgrpc.Logger.Vis implemented aslevelEnabler.Enabled(zapcore.Level(level - 1)), which conflatesgrpclog's verbosity with zap's severity. With WARN enabled,
V(2)returns true, so grpc-go thinks verbosity level 2 ispermitted and emits the message — which then gets formatted by
zapgrpc as a WARN entry. See uber-go/zap#1544.
Solution
Wrap the installed
grpclog.LoggerV2with afixedVerbosityLoggerwhose
V()compares the requested level against a fixed threshold(default 0) instead of the underlying zap severity enabler. This
restores grpclog's intended verbosity gating, so verbose messages
stop at grpc-go before formatting rather than being filtered out
of the log stream after the fact.
The default threshold of
0matches grpclog whenGRPC_GO_LOG_VERBOSITY_LEVELis unset.This approach:
V()mapping) rather thanstring-matching specific message contents.
V(2)+noise, including future grpc-goadditions, not just two cherry-picked patterns.
Info/Warning/Error)completely unchanged.
Testing
TestFixedVerbosity— assertsV(0)is enabled andV(1)/V(2)are not at the default threshold.
TestSeverityLevelsUnaffected— directWarning("…")stillfires at WARN, confirming the wrapper does not gate severity.
TestGRPCLoggercases continue to pass unchanged.