Add origin server tcp_info logging - #13667
Conversation
Expose origin TCP measurements so access logs can help distinguish network delay from origin processing time. Preserve a snapshot while the socket is available, discard it on retries, and require opt-in sampling with logging enabled to avoid unnecessary syscalls.
There was a problem hiding this comment.
🟡 Changes recommended
There are a couple of correctness/robustness issues in the new TCP_INFO sampling and verification code (potential uninitialized reads / unsupported-field handling and a test flake risk) that should be addressed before approval.
Once you've addressed the issues Copilot identified, you can request another Copilot review.
Pull request overview
Adds a new runtime configuration (proxy.config.http.log_server_tcp_info) and related access-log fields to capture a snapshot of origin-connection TCP_INFO values at origin response-header parse time, enabling RTT / RTT variation / retransmits / congestion window reporting without depending on the connection still being open at log-write time.
Changes:
- Add
TcpInfoSnapshotplumbing fromNetVConnection→HttpSM→TransactionLogData→LogAccessand register new log format symbols (srtt,srtv,sret,scwn). - Add config record + HTTP config wiring to enable/disable sampling.
- Add AuTest coverage via replay YAMLs plus a verifier script, and document the new config + log fields.
File summaries
| File | Description |
|---|---|
| tests/gold_tests/logging/verify_origin_tcp_info.py | Verifies access-log output contains expected cache result + TCP_INFO values per sampling mode. |
| tests/gold_tests/logging/replay/origin-tcp-info-retry.replay.yaml | Replay scenario ensuring a TCP_INFO sample from a first parent is not reused after a retry path. |
| tests/gold_tests/logging/replay/origin-tcp-info-global-disabled.replay.yaml | Replay scenario validating sampling is skipped when access logging is globally disabled. |
| tests/gold_tests/logging/replay/origin-tcp-info-enabled.replay.yaml | Replay scenario covering miss, hit, and “txn logging disabled at sampling time” behavior. |
| tests/gold_tests/logging/replay/origin-tcp-info-disabled.replay.yaml | Replay scenario validating default behavior (no sampling) reports -1 fields. |
| tests/gold_tests/logging/origin-tcp-info.rewrite.config | Uses header_rewrite to disable txn logging at sampling time for a specific request. |
| tests/gold_tests/logging/log-origin-tcp-info.test.py | Test driver running the replay scenarios and invoking the verifier script. |
| src/records/RecordsConfig.cc | Registers proxy.config.http.log_server_tcp_info. |
| src/proxy/logging/TransactionLogData.cc | Exposes origin TCP_INFO snapshot from the transaction’s HttpSM. |
| src/proxy/logging/LogAccess.cc | Marshals origin TCP_INFO fields as signed integers with -1 sentinel. |
| src/proxy/logging/Log.cc | Adds new log fields and symbols: srtt, srtv, sret, scwn. |
| src/proxy/http/HttpSM.cc | Samples TCP_INFO after successful origin response-header parsing and resets sample across attempts. |
| src/proxy/http/HttpConfig.cc | Wires the new config into HttpConfigParams. |
| src/iocore/net/P_UnixNetVConnection.h | Implements UnixNetVConnection::get_tcp_info() using getsockopt(TCP_INFO) and debug logging. |
| include/proxy/logging/TransactionLogData.h | Declares get_server_tcp_info() and includes TcpInfoSnapshot. |
| include/proxy/logging/LogAccess.h | Declares new marshalers and helper for origin TCP_INFO fields. |
| include/proxy/http/HttpSM.h | Adds server_tcp_info storage in the state machine. |
| include/proxy/http/HttpConfig.h | Adds log_server_tcp_info config param to HttpConfigParams. |
| include/iocore/net/TcpInfoSnapshot.h | Introduces a small POD struct for the sampled TCP_INFO subset. |
| include/iocore/net/NetVConnection.h | Adds a virtual get_tcp_info() hook with a safe default (returns false). |
| doc/admin-guide/logging/formatting.en.rst | Documents the new log field symbols and their semantics. |
| doc/admin-guide/files/records.yaml.en.rst | Documents proxy.config.http.log_server_tcp_info behavior and constraints. |
Review details
- Files reviewed: 22/22 changed files
- Comments generated: 4
- Review effort level: Lite
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
Avoid uninitialized TCP_INFO data and reporting unsupported retransmit counters as zero. Wait for complete log records so asynchronous writes cannot produce spurious test failures.
There was a problem hiding this comment.
🟢 Approval recommended
The implementation is opt-in, guarded appropriately, and includes targeted AuTest coverage plus clear documentation for both the record and new log fields.
Review details
- Files reviewed: 22/22 changed files
- Comments generated: 0 new
- Review effort level: Lite
| .. ts:cv:: CONFIG proxy.config.http.log_server_tcp_info INT 0 | ||
| :reloadable: | ||
|
|
||
| Enables sampling of ``TCP_INFO`` on the origin connection, so that the round | ||
| trip time to the origin can be logged. |
There was a problem hiding this comment.
What is the sample rate? Maybe I'm missing it, but I don't see the rate explained here.
|
|
||
| /** Read @c TCP_INFO from the underlying socket. | ||
| * | ||
| * @param info Filled in only when this returns @c true. |
| HttpSM::do_http_server_open(bool raw, bool only_direct) | ||
| { | ||
| // A failed new attempt must not report a previous origin's TCP_INFO. | ||
| server_tcp_info.reset(); |
There was a problem hiding this comment.
[P2] Clear the sample when following a redirect to a cached response
The reset points miss an internally followed redirect whose target is already fresh in cache. With number_of_redirections enabled and redirect_use_orig_cache_key=0, an origin 302 populates server_tcp_info and do_redirect() logs that response, then redirect_request() reuses the same HttpSM. HandleRequest() can proceed directly to CACHE_LOOKUP and serve the target without DNS_LOOKUP, do_http_server_open(), or setup_server_read_response_header(), so the final cache-hit log incorrectly repeats the redirect origin's srtt/srtv/sret/scwn instead of -1. Please clear the snapshot when beginning the redirected request, after logging the redirect response, and add a replay case that primes the target in cache before following an origin redirect to it.
Add
proxy.config.http.log_server_tcp_infoto log origin server TCP_INFO fields:srtt(smoothed RTT),srtv(RTT variation),sret(cumulative retransmits), andscwn(send congestion window).