Repository navigation
atenet-egress: log every failed request, sample successes at 1% - #2693
Conversation
Jeff Luo (JeffLuoo)
left a comment
Jeff Luo (JeffLuoo)
left a comment
There was a problem hiding this comment.
Thanks for this change. I have two comments to fix before merge. Both apply to the MITM chain and to the cleartext chain. The first one is about gRPC failures that the filter does not keep. The second one is about a sample decision that the actor can control.
| filter: | ||
| or_filter: | ||
| filters: | ||
| - status_code_filter: |
There was a problem hiding this comment.
This filter does not keep gRPC failures. A gRPC error comes back as HTTP 200 with a non-zero grpc-status in the trailers, or in a trailers-only response. Envoy's local replies to a gRPC request also use :status 200. Such a request has no response flag, so only the 1% sample logs it. The grpc_status field in the log format then almost never shows a failure, and the claim "every failure still recorded" is not true for gRPC traffic.
Please add a gRPC branch to the or_filter on both chains (here and the cleartext chain at line 660), and update wantSampledLogFilter:
- and_filter:
filters:
- header_filter:
header:
name: content-type
string_match: {prefix: application/grpc}
- grpc_status_filter: {exclude: true, statuses: [OK]}I limit the branch to gRPC requests on purpose. A grpc_status_filter alone can match plain HTTP 200 responses too. When a response has no grpc-status, Envoy maps the HTTP status to a gRPC code, and 200 maps to UNKNOWN. Please confirm the result with a request of each type.
There was a problem hiding this comment.
Good catch. The MITM chain routes gRPC, so those errors only reached the log through the sample. In 9290a43 both chains carry your and_filter branch, wantSampledLogFilter pins it per leg, and the blind-spots entry mentions it. The old filter logged none of the three errors below.
Checked on Envoy 1.39.4 with this exact filter block and access_log.sample at 0, against a small h2c origin:
| request | response | logged |
|---|---|---|
gRPC, grpc-status: 5 in trailers |
200 | yes |
gRPC, trailers-only grpc-status: 14 |
200 | yes |
gRPC to an Envoy direct_response: 403 (local reply) |
200, grpc-status: 7 |
yes |
gRPC OK, grpc-status: 0 in trailers |
200 | no |
plain HTTP/1.1 GET, no grpc-status |
200 | no |
{"ctype":"application/grpc","flags":"-","grpc_status":"NotFound","leg":"probe","path":"/svc/Err5","request_id":"1f2946d6-ca5d-4bbd-a4b8-218ffb1d50c9","status":200}
{"ctype":"application/grpc","flags":"-","grpc_status":"PermissionDenied","leg":"probe","path":"/svc/Denied","request_id":"32c3cae0-580d-4493-959e-bc0f83261eab","status":200}
| op: GE | ||
| value: {default_value: 400, runtime_key: access_log.min_status} | ||
| - response_flag_filter: {} | ||
| - runtime_filter: |
There was a problem hiding this comment.
Please set use_independent_randomness: true on this runtime_filter, and on the one in the cleartext chain at line 665. When the field is false (the default), Envoy takes the sample decision from x-request-id. The HCM does not set use_remote_address, so Envoy can keep an x-request-id that the actor sends. An actor that sends the same ID on each call, or that retries with one ID, then gets all of its successful requests logged or none of them. An actor can also pick an ID that keeps its successful requests out of the log. Independent sampling removes both problems, and the change is one line.
There was a problem hiding this comment.
Agreed. In 9290a43 both runtime_filters set use_independent_randomness: true, and the test pins it per leg. Without the field, one fixed x-request-id decided all of an actor's successes at once.
Envoy 1.39.4, same filter block, access_log.sample raised to 50 with POST /runtime_modify?access_log.sample=50, then 200 plain GETs that all carry one fixed x-request-id:
x-request-id |
without the field | with the field |
|---|---|---|
0a1b2c3d-0000-4000-8000-000000000001 |
0 / 200 | 104 / 200, rerun 90 / 200 |
00000000-0000-4000-8000-000000000001 |
200 / 200 | 97 / 200 |
7781ee8 to
9290a43
Compare
The MITM and cleartext chains wrote one access-log line per actor request. At 2,500 req/s on one replica, with the kubelet's default rotation, that keeps only 45 s of history. Both chains now log a request only when its status is 400 or above, when it is a gRPC request whose grpc-status is not OK, when it carries a response flag, or as a 1% sample of the rest. The sample decision no longer follows the actor's x-request-id.
9290a43 to
eaa1f19
Compare
Fixes #2685
The MITM and cleartext chains write one JSON access-log line per actor request. At 2,500 req/s on one replica that is 1.2 MB/s, and with the kubelet's default rotation only about 45 s of history survives, so a failure from a minute ago is already gone.
Both chains now log a request only when its status is 400 or above, when it carries a response flag, or as a 1% sample of the rest. At the same rate the log drops to 25 lines/s and the rotation window is over an hour, with every failure still recorded. The threshold and the sample rate are runtime keys,
access_log.min_statusandaccess_log.sample, so an operator can restore full logging at the admin port without a rollout. The log no longer counts successful requests per host;docs/metrics/substrate.yamlrecords that.Testing: the manifest test compares each per-request log's filter against the expected YAML and asserts no other access log carries one.
go test -race ./cmd/atenet/...andhack/verify/*.shpass.Prepared with help from an AI coding agent; reviewed and verified by the author.