apache / apache/trafficserver

SERVER_CLOSE milestone set before UA_BEGIN_WRITE on transform path causes negative o_body

Open
#12,942 1 comment 0 reactions 1 assignee Claimed by @bryancall View on GitHub
Bug HTTP Logging Transform
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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.