[squid-users] help with the error TCP_MISS_ABORTED/000

Wed Feb 28 04:00:29 UTC 2018

On 28/02/18 15:12, L A Walsh wrote:
> Juan Manuel P wrote:
>> I am using Squid Cache: Version 3.5.12, but some pages give me the
>> next error:
>>
>> 1/Feb/2018:18:14:40 -0300 || - || 10.12.43.20 ||
>> TCP_MISS_ABORTED/000|| GET ||
>> http://www.rionegro.gov.ar/download/images/00033494.jpg
>> <http://www.rionegro.gov.ar/download/images/00033494.jpg> || -
> ----
>    I don't know what causes it, but I see it frequently and have for a few
> years.  Currently am running 3.15.3.  Was told it might be due to some

Er, which version exactly?

> cache corruption -- but having removed it several times over the past
> few years, I sorta doubt that.  Also, I'm attempting https interception,
> now
> but wasn't when I first encountered this message...

It can come from many reasons. One has to look at all the clues about
where the message came from, which (if any) server was involved, how
long it took, etc.

I could write a book on the things and ways it *might* happen. But
whether any of that is relevant or just hand-wavey ideas is anyones
guess at present.

>From what I know about it currently; corruption HTTP cache entries might
be a side-effect, but very unlikely to be a cause of this.

Other types of caches used by Squid may be involved, eg the DNS cache
pointing Squid to a server IP that is not responding. But I don't recall
any instances of that data being corrupted, and the duration of the
transaction is far too short to have been some kind of timeout on the
server side of things (immediate TCP reject from invalid server IPs
shows up completely differently.)

* ABORTED almost always means the client[1] disconnected from the TCP
connection. That can happen for any number of reasons at the TCP, IP and
Ethernet layers which Squid is not party to.

... emphasis on "almost". In the case of CONNECT messages and NTLM
Pinned connections the server can also trigger disconnect for both
endpoints.

* HTTPS introduces several additional possible causes. Primarily that
CONNECT message server abort just mentioned. But also if SSL-Bump is
being done, any TLS errors that result in "terminate" action will also
show up as aborts at the TCP and HTTP(S) layers. Squid logging of those
cases has been a bit buggy and there may be issues still yet to be found
there.
 That does not explain the pre-HTTPS occurances. But also due to the
vague nature of the abort reason those earlier aborts may be completely
different in cause from your current ones.

The "/000" status means no HTTP reply was received from a server. Abort
can also happen any time *after* a server response is received, but
those should be logged with their status codes not 000.
 - That may be because no server was even contacted. ie the client
disconnected immediately, or during the wait for server DNS records to
arrive, or for any other reason the client has.

SSL-Bump clouds the issue a lot because it will naturally time some
amount of time to do any of its checks and any server contact for server
cert details etc. Again the client can disconnect for any number of
reasons during all that, with the same ABORTED/000 end result.

So. Maybe bug, maybe not. "insufficient data".

> 
>    Out of last 5000 requests in my squid log, I see 101 of the miss_aborted
> statuses.  I just wrote a note on stackexchange, then went to look for
> something on amazon (this is output from a squid log compression tool
> that was mostly for listing site, request time and size:  A few lines
> from no more than 15 minutes ago (usually shows time between requests, but
> periodically, there's a full timestamp)...
> 
>    Part of my shortening process removes the TCP_ before error messages,
> thus my error is just "MISS_ABORTED".
> 
> Since this is a grep of that shortened log, the time increments since
> last message are not referring to line immediately above in the grep:
> 
> 
> [0227_172940.00]  379ms; 0    (0/0) MISS_ABORTED/000 <Athenae [GET
> https://qa.sockets.stackexchange.com/ - 198.252.206.25 -]
>  +0.38   372ms; 0    (0/0) MISS_ABORTED/000 <Athenae [GET 
> https://qa.sockets.stackexchange.com/ - 198.252.206.25 -]
>  +0.01     1ms; 0    (0/0) MISS_ABORTED/000 <Athenae [GET
> https://images-na.ssl-images-amazon.com/images/I/61x0MG3xpeL._AC_UL160_SR160,160_.jpg
> - 54.230.117.34 -]
>  +0.00     0ms; 0    (-/-) MISS_ABORTED/000 <Athenae [GET
> https://images-na.ssl-images-amazon.com/images/I/813zL5eetaL._AC_UL160_SR160,160_.jpg
> - 54.230.117.34 -]
>  +0.00     0ms; 0    (-/-) MISS_ABORTED/000 <Athenae [GET
> https://images-na.ssl-images-amazon.com/images/I/61Uo2hXZlpL._AC_UL160_SR160,160_.jpg
> - 54.230.117.34 -]
>  +0.00     0ms; 0    (-/-) MISS_ABORTED/000 <Athenae [GET
> https://images-na.ssl-images-amazon.com/images/I/71XggjYZ7qL._AC_UL160_SR160,160_.jpg
> - 54.230.117.34 -]
>  +0.00     1ms; 0    (-/0) MISS_ABORTED/000 <Athenae [GET
> https://images-na.ssl-images-amazon.com/images/I/71LT8PAs-OL._AC_UL160_SR160,160_.jpg
> - 54.230.117.34 -]
>  +0.00     1ms; 0    (-/0) MISS_ABORTED/000 <Athenae [GET
> https://images-na.ssl-images-amazon.com/images/I/51X+70QICxL._AC_UL160_SR160,160_.jpg
> - 54.230.117.34 -]
> [0227_173215.00]   16ms; 0    (0/0) MISS_ABORTED/000 <Athenae [GET
> https://www.amazon.com/gp/uedata?ul&v=0.200071.0&id=TXSV6J9MMKFJ764232PB&ctb=1&m=1&sc=TXSV6J9MMKFJ764232PB&pc=3758697&tc=-286&hob=1&hoe=3&ul=3758697&t=1519781535329&csmtags=mouseHit&pty=Detail&spty=Glance&pti=B079GH97R9&tid=TXSV6J9MMKFJ764232PB&aftb=1
> - 23.192.244.68 -]
> ====================================
> 
> 
> Of note -- a bunch were in trying to fetch a sockets address on
> stackexchange, , while most of the amazon lines seem to be referring to
> jpgs.  Anyway, I too would be interested if you find the answer.

If anyone seeing these is up for some detective work I'm interested in
whether there is any kind of pattern for the real timing between those
lines, and between a failure and previous/next successful transaction to
the same server.
 Bonus points for getting the info with port numbers to see if there is
a pattern hidden in the client connection state.

While its nice to know the frequency is decreasing (IIRC first reporters
had unpleasantly large amounts, now to this ~2% of yours) that does not
really tell much of use for resolving it (or 'them' if multiple issues).

> 
> Just thought I'd mention that your seeing the message isn't unique.
> 
> Found someone else who asked the same question back in May 2015...
> 

Nod. It has been cropping up since the ABORTED log tag was first added,
and "000" status since long before that.

Amos