SERVER_CLOSE milestone set before UA_BEGIN_WRITE on transform path causes negative o_body

[bryancall]

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).