Repository navigation
Sync the Envoy access log proto and leave unmeasurable sidecar internal latencies out - #14148
Conversation
There was a problem hiding this comment.
🟢 Approval recommended
The focused guards preserve legacy behavior, have regression coverage, and leave no identified blocking issues.
No open issues 🎉
What changed in this PR
Corrects Envoy ALS sidecar request latency after retries, following the earlier whole-second precision fix.
Changes:
- Synchronizes Envoy access-log protos with v1.40.0.
- Reports zero internal request latency for multiple attempts, with HTTP and TCP regression tests.
- Adds Envoy notices and changelog entries.
| File | Description |
|---|---|
| oap-server/server-receiver-plugin/receiver-proto/src/main/proto/envoy/data/accesslog/v3/accesslog.proto | Updates the schema, including attempt counts. |
| oap-server/server-receiver-plugin/receiver-proto/src/main/proto/envoy/annotations/deprecation.proto | Adds required deprecation annotations. |
| oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/test/java/org/apache/skywalking/oap/server/receiver/envoy/als/LogEntry2MetricsAdapterTest.java | Tests single-attempt and retry behavior. |
| oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/tcp/TCPLogEntry2MetricsAdapter.java | Guards latency after retried TCP connections. |
| oap-server/server-receiver-plugin/envoy-metrics-receiver-plugin/src/main/java/org/apache/skywalking/oap/server/receiver/envoy/als/LogEntry2MetricsAdapter.java | Guards latency after HTTP retries. |
| NOTICE | Adds Envoy attribution. |
| docs/en/changes/changes.md | Records latency, proto, and notice changes. |
| dist-material/release-docs/NOTICE | Adds Envoy attribution to binary distributions. |
Review effort: Balanced
70e1a60 to
f75b909
Compare
| service_sidecar_internal_req_latency_nanos = from(Service.sideCar.internalRequestLatencyNanos).filter(sideCar.internalRequestLatencyNanos >= 0).longAvg(); | ||
| service_sidecar_internal_resp_latency_nanos = from(Service.sideCar.internalResponseLatencyNanos).filter(sideCar.internalResponseLatencyNanos >= 0).longAvg(); |
There was a problem hiding this comment.
@kezhenxu94 @wankai123 I accidently noticed this issues. The newer Envoy has a chance to enhnace. But can't fix this in old Envoy/Istio.
There was a problem hiding this comment.
Which Istio versions are enhanced, read from the Envoy commit each istio/proxy release branch pins (ENVOY_SHA) and from Envoy's own source:
| Part of this PR | What it needs from Envoy | Istio versions enhanced |
|---|---|---|
A missing timing, or nothing sent upstream, is left out instead of counted as 0 |
nothing new | all |
| The internal request latency of a retried or hedged request is left out | upstream_request_attempt_count, sent by the gRPC ALS since Envoy 1.24 |
Istio 1.16+: 1.16 ships Envoy 1.24; 1.15 ships Envoy 1.23, which doesn't send it |
| Envoy's own replies, such as the 504 of a timeout during a retry backoff, are left out of the internal response latency | response_code_details, sent since Envoy 1.12 or earlier |
everything that sends the attempt count, and older |
On an older Envoy the field is just absent. OAP reads 0 / "" and keeps the previous behaviour, so nothing breaks; the retry and backoff cases aren't detected there.
Our e2e matrix covers Istio 1.21–1.29 (Envoy 1.29–1.37), so every tested version is enhanced. Istio 1.30 and 1.31 (Envoy 1.38 and 1.39) aren't in the matrix, but they send both fields too. The proto is synced to Envoy v1.40.0 only as a file version; nothing in this PR needs Envoy 1.40.
…al latencies out Sync envoy/data/accesslog/v3/accesslog.proto with Envoy v1.40.0 and add the envoy/annotations/deprecation.proto it imports. The vendored copy dated from 2022 and had no upstream_request_attempt_count. The Envoy ALS sidecar internal latencies now leave out what the access log cannot measure, instead of counting it as 0: - the internal request latency when Envoy retried or hedged the request, or the TCP proxy took more than one connect attempt (upstream_request_attempt_count above 1), or nothing went upstream. Envoy measures the upstream timings from the start of the downstream request or connection, so the time to the first upstream byte can include the earlier attempts and the delays between them. - the internal response latency when a timing is absent, or the response details are anything but via_upstream, as for Envoy's own 504 of a timeout during a retry backoff, which can carry an earlier attempt's upstream timing. An upstream response that a later reset or timeout ended is conservatively left out too. The adapters write -1 for such a latency, and the internal latency metrics in mesh.oal skip it with filter(... >= 0). A customized mesh.oal needs the same filters, or the -1 values are averaged in. That filter needed an OAL fix: comparing a long or double source field with a number failed to compile, because the generated code passed the number as an int and Javassist does not widen it to find match(long, long). The OAL enricher now resolves the compared field's type and writes the number as a literal of it, 0L or 0.0; a cast would not do, as Javassist overflows the int inside (long)(3000000000). Filters on other fields, int ones included, generate the same code. Also add the Envoy project's NOTICE to NOTICE and to the binary distribution's NOTICE, for the Envoy proto files SkyWalking bundles.
f75b909 to
792aaed
Compare
Fix the Envoy ALS sidecar internal latencies counting what the access log cannot measure
Follow-up to #14147. All references are to Envoy v1.40.0.
Why the bug exists.
time_to_*field from the start of the downstream request (source/common/stream_info/utility.cc,duration()), and each retry attempt installs fresh upstream timing on the logged StreamInfo (source/common/router/upstream_request.cc).time_to_first_upstream_tx_byte, which OAP reads as the internal request latency, includes the earlier attempts' wait on the upstream and the backoff. It is not a sum of per-attempt sidecar times, so dividing by the attempt count does not recover a per-attempt value.tcp_proxy.cc,setAttemptCount).0for a missing timing.0still counts inlongAvg()and pulls the average down.How it is fixed.
envoy/data/accesslog/v3/accesslog.protois a byte-identical copy of the Envoy v1.40.0 file. The previous copy dated from Sync proto buffers files from upstream Envoy #8434 (2022-01) and had noupstream_request_attempt_count. The change is additive only. Also added:envoy/annotations/deprecation.proto, which the new file imports.-1, and the 14 internal latency metrics inmesh.oalskip it withfilter(sideCar.internalRequestLatencyNanos >= 0)(and the response-side equivalent).upstream_request_attempt_count > 1or when nothing went upstream.response_code_detailsis set to anything butvia_upstream. An empty value, from an older Envoy, still counts. This also conservatively leaves out an upstream response that a later reset or timeout ended, because Envoy then overwrites the details.0and is treated as a single attempt.mesh.oalneeds the same>= 0filters, or the-1values are averaged in.longordoublesource field with a number never compiled. The enricher wrote the number as anint, and the comparison matchers have nomatch(long, int)overload, since Javassist does not widen arguments.MetricDefinitionEnrichernow resolves the compared field's type by reflection and writes the number as a literal of that type:0Lor0.0.intinside(long)(3000000000)to-1294967296.RuntimeOALGenerationTestoutput between master's enricher and this one, and only themesh.oalclasses differ.NOTICEanddist-material/release-docs/NOTICE. It had been missing since the Envoy protos were first vendored.Tests.
LogEntry2MetricsAdapterTestcovers: retry, retried CONNECT, one attempt, nothing upstream, plain TCP proxy,via_upstream, and Envoy's 504 during a backoff. Fix Envoy ALS sidecar internal latencies dropping whole seconds #14147's three assertions change from0to-1, with the maintainer's approval.via_upstreamcheck, the 504 test fails withexpected: <-1> but was: <500000000>.MetricDefinitionEnricherTestadds a nestedlongfilter test and a test that compiles3000000000L/3000000000.0with Javassist and runs them.Known limits, left as follow-ups.
OAL numeric
in [...], cast/map filters,doubleequality, andlong/doubleinequality are still unsupported. These are pre-existing.The per-attempt
upstream_logandaccess_log_typefiltering are possible later improvements.If this pull request closes/resolves/fixes an existing issue, replace the issue number. Closes #.
Update the
CHANGESlog.