bryancall opened a new issue, #12942: URL: https://github.com/apache/trafficserver/issues/12942
## Description When a response goes through a transform plugin, `setup_server_transfer_to_transform()` starts the origin-to-transform tunnel **before** the `API_SEND_RESPONSE_HDR` callout runs. For small, fast origin responses, the origin sends the complete body and closes the connection (setting `SERVER_CLOSE` via `tunnel_handler_server()`) while ATS is still processing the response through the transform pipeline. `UA_BEGIN_WRITE` is not set until later when the transform output triggers the `SEND_RESPONSE_HDR` path. This causes `o_body = SERVER_CLOSE - UA_BEGIN_WRITE` to be negative in the `msdms` log fields. ## Impact | Field | Definition | Symptom | Rate | |-------|-----------|---------|------| | `o_body` | `SERVER_CLOSE - UA_BEGIN_WRITE` | Negative values (-2 to -612ms) | ~0.1% of requests | The time is not lost — it shifts to `c_xfer` (`SM_FINISH - SERVER_CLOSE`), which absorbs the gap. But the negative value is confusing in logs and breaks chain sum validation. ## Characteristics All 389 observed cases (across 400K log lines) share these traits: - **CRC:** TCP_MISS (88%), TCP_REFRESH_MISS (5%), TCP_IMS_MISS (4%), ERR_CLIENT_READ_ERROR (0.5%) - **Status:** 100% are c_status=200, o_status=200 — successful responses, no client aborts - **Method:** 100% GET - **Response size:** Small — p50 = 684 bytes on origin side - **`o_proc` elevated:** p50 = 23ms (response hook processing takes significant time) - **Correlation:** `|o_body|` matches `o_proc` within 2ms on 93% of cases — origin closes during response hook processing - **Protocol:** All HTTP/1.1 to origin ## Root Cause Two response paths exist in `HttpSM::set_next_state()`: **Without transform (correct ordering):** 1. `API_SEND_RESPONSE_HDR` → `UA_BEGIN_WRITE` set 2. Hooks complete → `setup_server_transfer()` → tunnel starts 3. Origin closes → `SERVER_CLOSE` set 4. Order: `UA_BEGIN_WRITE` < `SERVER_CLOSE` ✓ **With transform (broken ordering):** 1. `setup_server_transfer_to_transform()` → tunnel starts immediately 2. Origin sends small response and closes → `SERVER_CLOSE` set via `tunnel_handler_server()` 3. Transform processes data → eventually triggers `SEND_RESPONSE_HDR` 4. `UA_BEGIN_WRITE` set 5. Order: `SERVER_CLOSE` < `UA_BEGIN_WRITE` ✗ `SERVER_CLOSE` is set in `tunnel_handler_server()` (`HttpSM.cc:3162`). `UA_BEGIN_WRITE` is set in `do_api_callout_internal()` (`HttpSM.cc:5864`). ## Possible Fix Set `UA_BEGIN_WRITE` earlier on the transform path — either in `setup_server_transfer_to_transform()` before `tunnel.tunnel_run()`, or when the transform-to-client transfer begins in `setup_transfer_from_transform()`. Alternatively, clamp `o_body` to 0 in the `msdms` logging layer when the value would be negative. ## Data Observed on 400K production squid.log lines from SWB incubator (e17/e18, ATS 10.0.0.144). -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
