SERVER_CLOSE milestone set before UA_BEGIN_WRITE on transform path causes negative o_body
- Dominant language
- C++
- Stars
- 2k
- Forks
- 874
- Avg merge
- 6d 15h
- Merged PRs (30d)
- 46
Description
## 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 using the Phase 1 milestone logging format (15 per-phase timing fields via `msdms`).
Contributor guide
Assessment
This issue has not been assessed yet.