[squid-users] Some requests not being passed/processed by squid

[Alex Rousskov]

On 8/10/23 05:20, Ralf Hildebrandt wrote:
> We're running a cluster of 4 identical Squid proxies.
> 
> In order to check the functionality of each cluster node, were using
> ldirectord which is querying each realserver like this:
> 
> GET http://127.0.0.1/proxytest.cgi

I assume there is HTTP/1.x at the end and some request headers after the 
request line.


> Now we were seen some odd warning in our graphs, clusternodes being
> removed and added back to the cluster only a few seconds later.
> 
> I found that these requests for http://127.0.0.1/proxytest.cgi were
> sometimes (seldom -- maybe once/twice per day) failing.
> 
> In the squid access.log I'm seeing this as:
> ===========================================
> 
> Thu Aug 10 10:32:54 2023    115 141.42.5.218 TCP_REFRESH_ABORTED/200 0 141 GET http://127.0.0.1/proxytest.cgi - HIER_DIRECT/127.0.0.1 text/plain accessRule=- 56680
> Thu Aug 10 10:33:02 2023      0 141.42.5.218 NONE_NONE_ABORTED/000 0 141 GET http://127.0.0.1/proxytest.cgi - HIER_NONE/- - accessRule=- -
> Thu Aug 10 10:33:07 2023      0 141.42.5.218 NONE_NONE_ABORTED/000 0 141 GET http://127.0.0.1/proxytest.cgi - HIER_NONE/- - accessRule=- -
> 
> as opposed to the normal:
> =========================
> 
> Thu Aug 10 11:02:45 2023      5 141.42.5.218 TCP_REFRESH_MODIFIED/200 314 141 GET http://127.0.0.1/proxytest.cgi - HIER_DIRECT/127.0.0.1 text/plain accessRule=- 51940
> 
> My Logformat:
> =============
> 
> logformat squid-sourceport  %ts.%03tu %6tr %>a %Ss/%03>Hs %<st %>st %rm %ru %[un %Sh/%<a %mt accessRule=%{accessRule}note %<lp
> 
> * I replaced the the secondssince1970 timestamp with a human readable timeformat
> * Last colument in the log is the sourceport used by squid
> 
> I checked nginx logs on that machine and found that the requests for
> http://127.0.0.1/proxytest.cgi never reached nginx (for the three
> incidents marked above)
> 
> So my questions:
> ================
> 
> What are TCP_REFRESH_ABORTED/200 and (which looks more dire) NONE_NONE_ABORTED/000?


I can only describe a few _possible_ outcomes. They may not match what 
is actually happening in your specific use cases because I have not 
checked all the necessary details, because of Squid bugs, and because 
several different outcomes may map to the same access.log line, 
especially in older Squids, especially in Squids that do not access-log 
%err_code/%err_detail.

* TCP_REFRESH_ABORTED/200: Squid found a matching stale cached response 
and decided to revalidate it with the origin server. After (or while or 
just before) talking to the origin server and/or while (or just before) 
sending a 200 OK response to the client, the client (or something else) 
closed the client-Squid connection.

* NONE_NONE_ABORTED/000: The client (or something else) closed 
client-Squid connection much earlier than what is described in the 
TCP_REFRESH_ABORTED/200 case above, even before Squid found a matching 
stale response in its cache, if any, or even before Squid checked that 
cache. Technically, logging NONE_NONE is a Squid bug. Squid should log 
something like TCP_ABORTED instead.

I recommend logging %err_code/%err_detail. Logging Cache-Status response 
header may also be useful.


HTH,

Alex.