3.5.28 partial content getting HIT but not sending

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

3.5.28 partial content getting HIT but not sending

Heiler Bemerguy

I got today these hits repeating all day long:

1542992067.660      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542992067.717      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542992067.779      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip

a tcpdump shows me a partial get from client:

GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz HTTP/1.1
Host: archive.canonical.com
Range: bytes=3790651-
If-Range: Tue, 20 Nov 2018 13:54:54 GMT
User-Agent: Debian APT-HTTP/1.3 (1.6.6)


and proxy anwers like this:

HTTP/1.1 206 Partial Content
Date: Thu, 22 Nov 2018 10:40:20 GMT
Server: Apache/2.4.18 (Ubuntu)
Last-Modified: Tue, 20 Nov 2018 13:54:54 GMT
ETag: "1d1c25d-57b18fa72c3e2"
Accept-Ranges: bytes
Content-Type: application/x-gzip
Age: 108770
Warning: 113 proxy (squid) This cache hit is still fresh and more than 1 day old
Connection: keep-alive
Content-Range: bytes 3790651-30523996/30523997
Content-Length: 26733346

But there isn't much being transfered after it. And it should transfer 26,733,346 bytes, right? But look at the tcp packet capture right after the above one:

13:53:10.070860 IP 10.1.10.9.3080 > 10.15.3.137.43098: Flags [F.], seq 428, ack 254, win 33, options [nop,nop,TS val 70122782 ecr 1622121716], length 0
[hidden email]
.

......Z.-.qpl"Z...!!......
.-..`...
13:53:10.085478 IP 10.15.3.137.43098 > 10.1.10.9.3080: Flags [.], ack 428, win 237, options [nop,nop,TS val 1622121737 ecr 70122782], length 0
E..4..@.?...
...
.
        .Z..pl"Z.-.q.....a.....
`..     .-..
13:53:10.103003 IP 10.15.3.137.43098 > 10.1.10.9.3080: Flags [F.], seq 254, ack 429, win 237, options [nop,nop,TS val 1622121737 ecr 70122782], length 0
E..4..@.?...
...
.
        .Z..pl"Z.-.r....._.....
`..     .-..
13:53:10.103024 IP 10.1.10.9.3080 > 10.15.3.137.43098: Flags [.], ack 255, win 33, options [nop,nop,TS val 70122790 ecr 1622121737], length 0

It seems the proxy just closes the connection, then the client connects again and tries to get the same part everytime... There's nothing unusual on cache*.log

I think this file type is being "treated" by this pattern_refresh, I don't know if it would mess with anything, I think probably not:

refresh_pattern -i \.(udeb|exe|ms[iup]|xz|xml|bz2|gz|deb|rpm|bin|zip|ax|rpm|app|jar|pkg|apk|mar|nzp|dat|iop|xpi|dmg|dds|rar|thor|nar|gpf|lzma2)\??$ 120960 90% 120960 ignore-no-store ignore-private override-e
xpire store-stale override-lastmod


-- 
Atenciosamente,

Heiler Bensimon Bemerguy - CINBESA
Analista de Redes, Wi-Fi,
Virtualização e Serviços Internet
(55) 91 98151-4894

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: 3.5.28 partial content getting HIT but not sending

Heiler Bemerguy

Hum, disabling that refresh_pattern and -k reconfigure seems to have fixed it.. but.. why?


-- 
Atenciosamente,

Heiler Bensimon Bemerguy - CINBESA
Analista de Redes, Wi-Fi,
Virtualização e Serviços Internet
(55) 91 98151-4894
Em 23/11/2018 14:02, Heiler Bemerguy escreveu:

I got today these hits repeating all day long:

1542992067.660      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542992067.717      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542992067.779      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip

a tcpdump shows me a partial get from client:

GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz HTTP/1.1
Host: archive.canonical.com
Range: bytes=3790651-
If-Range: Tue, 20 Nov 2018 13:54:54 GMT
User-Agent: Debian APT-HTTP/1.3 (1.6.6)


and proxy anwers like this:

HTTP/1.1 206 Partial Content
Date: Thu, 22 Nov 2018 10:40:20 GMT
Server: Apache/2.4.18 (Ubuntu)
Last-Modified: Tue, 20 Nov 2018 13:54:54 GMT
ETag: "1d1c25d-57b18fa72c3e2"
Accept-Ranges: bytes
Content-Type: application/x-gzip
Age: 108770
Warning: 113 proxy (squid) This cache hit is still fresh and more than 1 day old
Connection: keep-alive
Content-Range: bytes 3790651-30523996/30523997
Content-Length: 26733346

But there isn't much being transfered after it. And it should transfer 26,733,346 bytes, right? But look at the tcp packet capture right after the above one:

13:53:10.070860 IP 10.1.10.9.3080 > 10.15.3.137.43098: Flags [F.], seq 428, ack 254, win 33, options [nop,nop,TS val 70122782 ecr 1622121716], length 0
[hidden email]
.

......Z.-.qpl"Z...!!......
.-..`...
13:53:10.085478 IP 10.15.3.137.43098 > 10.1.10.9.3080: Flags [.], ack 428, win 237, options [nop,nop,TS val 1622121737 ecr 70122782], length 0
E..4..@.?...
...
.
        .Z..pl"Z.-.q.....a.....
`..     .-..
13:53:10.103003 IP 10.15.3.137.43098 > 10.1.10.9.3080: Flags [F.], seq 254, ack 429, win 237, options [nop,nop,TS val 1622121737 ecr 70122782], length 0
E..4..@.?...
...
.
        .Z..pl"Z.-.r....._.....
`..     .-..
13:53:10.103024 IP 10.1.10.9.3080 > 10.15.3.137.43098: Flags [.], ack 255, win 33, options [nop,nop,TS val 70122790 ecr 1622121737], length 0

It seems the proxy just closes the connection, then the client connects again and tries to get the same part everytime... There's nothing unusual on cache*.log

I think this file type is being "treated" by this pattern_refresh, I don't know if it would mess with anything, I think probably not:

refresh_pattern -i \.(udeb|exe|ms[iup]|xz|xml|bz2|gz|deb|rpm|bin|zip|ax|rpm|app|jar|pkg|apk|mar|nzp|dat|iop|xpi|dmg|dds|rar|thor|nar|gpf|lzma2)\??$ 120960 90% 120960 ignore-no-store ignore-private override-e
xpire store-stale override-lastmod

-- 
Atenciosamente,

Heiler Bensimon Bemerguy - CINBESA
Analista de Redes, Wi-Fi,
Virtualização e Serviços Internet
(55) 91 98151-4894


_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users


_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: 3.5.28 partial content getting HIT but not sending

Amos Jeffries
Administrator
On 24/11/18 6:28 am, Heiler Bemerguy wrote:
> Hum, disabling that refresh_pattern and -k reconfigure seems to have
> fixed it.. but.. why?
>

Something else is going on which is not visible in the details you have
shown.

 - is the TCP connection containing a message pipeline?
 if so the data and FIN may be related to a previous response message in
that pipeline.

 - are other refresh patterns being used (probably yes) ?
  - what are they? (before and after the change)

 - what did your cache.log have to say at the time of the connection
termination? (may need debug level 2 or 5 enabled)


Also, you were using override-* and ignore-* settings in that
refresh_pattern that are not necessary for the Debian/Ubuntu servers.

 At best they will be doing nothing to these responses (ie
ignore-no-store, ignore-private do nothing to Debian/Ubuntu responses).

 Some will be causing *worse* caching service from the proxy.
override-lastmod with your small [84 day] expiry vastly reduces the
_years_ these objects can actually be cached for, and prevents IMS
revalidation being used to determine changes properly and store
un-changed things longer. NP: Debian/Ubuntu official repositories do
fully support IMS revalidation.


Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: 3.5.28 partial content getting HIT but not sending

Heiler Bemerguy
No doubt, the connections were really being closed by the proxy itself, LIKE it was finished sending the request. It was like a loop, so it was infinite connections one right after another, but not in parallel.. the fin-packets and everything else were "in order" judgjing by their SEQ values too.

There were other refresh_patterns but none matching it. I didn't enable debug options but I can try to reproduce it.. anyway the .conf was like that for years and this was the first time a "loop" like this occurred. I upgraded from 3.5.27 to 3.5.28 but I think nothing about this was modified recently, right..?

I know most refresh_pattern options were being ignored/wrong, that's why I've disabled it altogether, and right after it, the proxy replied to the client with a TCP_REFRESH_MODIFIED instead of a TCP_HIT and the loop was gone.
The remaining options are:
refresh_pattern . 0 80% 1440
reload_into_ims off
quick_abort_min 0 KB
quick_abort_max 0 KB
quick_abort_pct 95

with no range_offset_limits

look how tiny (427 bytes) all the responses were.. and a HIT for a range request is almost a miracle here.. lol (RockStore)

1542994021.243      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542994021.326      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542994021.399      2 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542994021.514      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542994021.614      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542994021.718      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542994021.824      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542994021.966      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542994022.124      1 10.15.3.137 TCP_HIT/206 427 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_NONE/- application/x-gzip
1542994036.811  14390 10.15.3.137 TCP_REFRESH_MODIFIED/206 26733678 GET http://archive.canonical.com/pool/partner/a/adobe-flashplugin/adobe-flashplugin_20181120.1.orig.tar.gz - HIER_DIRECT/91.189.92.150 application/x-gzip


-- 
Atenciosamente,

Heiler Bensimon Bemerguy - CINBESA
Analista de Redes, Wi-Fi,
Virtualização e Serviços Internet
(55) 91 98151-4894
Em 24/11/2018 03:33, Amos Jeffries escreveu:
On 24/11/18 6:28 am, Heiler Bemerguy wrote:
Hum, disabling that refresh_pattern and -k reconfigure seems to have
fixed it.. but.. why?

Something else is going on which is not visible in the details you have
shown.

 - is the TCP connection containing a message pipeline?
 if so the data and FIN may be related to a previous response message in
that pipeline.

 - are other refresh patterns being used (probably yes) ?
  - what are they? (before and after the change)

 - what did your cache.log have to say at the time of the connection
termination? (may need debug level 2 or 5 enabled)


Also, you were using override-* and ignore-* settings in that
refresh_pattern that are not necessary for the Debian/Ubuntu servers.

 At best they will be doing nothing to these responses (ie
ignore-no-store, ignore-private do nothing to Debian/Ubuntu responses).

 Some will be causing *worse* caching service from the proxy.
override-lastmod with your small [84 day] expiry vastly reduces the
_years_ these objects can actually be cached for, and prevents IMS
revalidation being used to determine changes properly and store
un-changed things longer. NP: Debian/Ubuntu official repositories do
fully support IMS revalidation.


Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users


_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: 3.5.28 partial content getting HIT but not sending

Amos Jeffries
Administrator
On 25/11/18 5:24 am, Heiler Bemerguy wrote:

> No doubt, the connections were really being closed by the proxy itself,
> LIKE it was finished sending the request. It was like a loop, so it was
> infinite connections one right after another, but not in parallel.. the
> fin-packets and everything else were "in order" judgjing by their SEQ
> values too.
>
> There were other refresh_patterns but none matching it. I didn't enable
> debug options but I can try to reproduce it.. anyway the .conf was like
> that for years and this was the first time a "loop" like this occurred.
> I upgraded from 3.5.27 to 3.5.28 but I think nothing about this was
> modified recently, right..?
>

3.5.28 is now treating the Content-Range header better - ignoring it in
server responses where it is not valid. Older versions were truncating
responses. Wild guess but I suspect the object stored in cache
previously may have been one of those incorrectly truncated ones or
something like that.

Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users