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

[bryancall]

Still present on master as of 052d4a4984. Re-checked the milestone ordering today.

One correction to the description above: UA_BEGIN_WRITE is now marked in three places, not one. HttpSM::set_next_state() marks it for SERVER_READ and for SERVE_FROM_CACHE, and do_api_callout_internal() marks it for API_SEND_RESPONSE_HDR. The TRANSFORM_READ case, which calls setup_transfer_from_transform(), sits directly above the other two in that same switch and is the only one of the three transfer paths that does not mark it. That is the whole gap.

So the fix is narrower than "set it earlier somewhere on the transform path": mark UA_BEGIN_WRITE in the TRANSFORM_READ case, next to tunnel.tunnel_run(), exactly as SERVER_READ and SERVE_FROM_CACHE already do. That makes the three transfer paths consistent and puts the milestone at the point the client write actually begins, rather than at the response-header hook.

I would not clamp the negative value in the logging layer. The ordering is the defect, and clamping would hide it while leaving the chain sum wrong.