[squid-users] Squid transparent not caching apt requests from deb.debian.org

[Alex Rousskov]

On 4/7/20 8:48 PM, zrm wrote:

> https://www.trustiosity.com/squid/cache-debug.log.xz

I found the reason for the difference.

After the destination IP address of your apt requests fails Host header
validation, Squid marks the request as "not cachable":

> hostHeaderIpVerify: IP 151.101.248.204:80 does not match from-Host IP 151.101.202.133
> hostHeaderIpVerify: FAILED to validate IP 151.101.248.204:80
> clientInterpretRequestHeaders: REQ_CACHABLE = NOT SET


After the destination IP address of your wget requests passes Host
header validation, Squid marks the request as "cachable":

> hostHeaderIpVerify: validated IP 151.101.202.133:80
> clientInterpretRequestHeaders: REQ_CACHABLE = SET


N.B. The log lines above have been slightly adjusted for readability
(this particular raw output is rather difficult to interpret correctly
IMO), but you can easily find raw lines if you look for the preserved
function names.


I hope others on the list will guide you towards a resolution of this
problem.


HTH,

Alex.

> On 4/6/20 11:49, Alex Rousskov wrote:
>> On 4/4/20 8:02 PM, zrm wrote:
>>> Attached cache.log excerpt for wget-wget-apt-apt-wget-wget. It answers
>>> the apt requests from the cache once it's in there, it just won't cache
>>> it to begin with when apt makes the request
>>
>> Thank you for sharing this log. I agree with your conclusion. The apt
>> query results in cache revalidation and does not purge the already
>> cached copy. This conclusion eliminates a few suspects.
>>
>> There is probably something special about the combination of an apt
>> request and a 200 OK miss response that prevents Squid from caching that
>> response. I do not see anything wrong in the logs you have already
>> already posted. Perhaps others will spot something.
>>
>> If you get no better responses, please post a link to a compressed
>> apt-apt-wget-wget log, starting from a cache that does not contain the
>> response in question and after enabling elevated Squid debugging with
>> "squid -k debug" or similar. You can find more instructions about
>> debugging individual transactions at
>> https://wiki.squid-cache.org/SquidFaq/BugReporting#Debugging_a_single_transaction
>>
>>
>> A detailed apt-apt-wget-wget log should tell us why Squid is refusing to
>> cache a 200 OK response to the apt query but caches a very similar
>> response to a very similar wget query.
>>
>>
>> Thank you,
>>
>> Alex.
>>
>>
>>
>>> [wget] 1586041686.600    725 192.168.111.55 TCP_MISS/200 1281195 GET
>>> http://deb.debian.org/debian/pool/main/v/vim/vim_8.1.0875-5_amd64.deb -
>>> ORIGINAL_DST/199.232.66.133 application/x-debian-package
>>> [wget] 1586041710.518    107 192.168.111.55 TCP_REFRESH_UNMODIFIED/200
>>> 1281232 GET
>>> http://deb.debian.org/debian/pool/main/v/vim/vim_8.1.0875-5_amd64.deb -
>>> ORIGINAL_DST/199.232.66.133 application/x-debian-package
>>> [apt] 1586041733.058     69 192.168.111.55 TCP_REFRESH_UNMODIFIED/200
>>> 1281234 GET
>>> http://deb.debian.org/debian/pool/main/v/vim/vim_8.1.0875-5_amd64.deb -
>>> ORIGINAL_DST/151.101.200.204 application/x-debian-package
>>> [apt] 1586041753.971    101 192.168.111.55 TCP_REFRESH_UNMODIFIED/200
>>> 1281234 GET
>>> http://deb.debian.org/debian/pool/main/v/vim/vim_8.1.0875-5_amd64.deb -
>>> ORIGINAL_DST/151.101.200.204 application/x-debian-package
>>> [wget] 1586041769.162    160 192.168.111.55 TCP_REFRESH_UNMODIFIED/200
>>> 1281232 GET
>>> http://deb.debian.org/debian/pool/main/v/vim/vim_8.1.0875-5_amd64.deb -
>>> ORIGINAL_DST/199.232.66.133 application/x-debian-package
>>> [wget] 1586041786.916     71 192.168.111.55 TCP_REFRESH_UNMODIFIED/200
>>> 1281232 GET
>>> http://deb.debian.org/debian/pool/main/v/vim/vim_8.1.0875-5_amd64.deb -
>>> ORIGINAL_DST/151.101.250.133 application/x-debian-package
>>>
>>>> BTW, you probably do not need to make ALL,2 logs pretty -- we can
>>>> figure
>>>> out what happens based on Squid messages if you submit one transaction
>>>> at a time and disclose transaction sequence. You can just post (a link
>>>> to) raw (or sanitized) logs. Compress them if they are too big.
>>>
>>>> Before sharing the logs, please double check that the problem you want
>>>> to address was reproduced during the test.
>>>
>>> In this case we start with wget and then it is already in the cache for
>>> the requests made by apt. The problem is the data not being cached when
>>> apt makes the request and it isn't already there. The apt requests do
>>> get answered from the cache if it is already there.
>>>
>>> The headers from the previous email show what happens when apt makes the
>>> request and it's not already in the cache.
>>>
>>>>> Last-Modified: Sat, 15 Jun 2019 17:46:35 GMT
>>>>> ETag: "1389dc-58b605823fa6e"
>>>>> Cache-Control: public, max-age=2592000
>>>>> Content-Length: 1280476
>>>>> Age: 4248100
>>>>
>>>> FWIW: The object is 4'248'100 seconds old. The object max-age is
>>>> 2'592'000 seconds. Your Squid is probably using an internal max-age of
>>>> 259'200 seconds, so Squid will require cache hit revalidation during
>>>> subsequent transactions after Squid caches the object (if it caches
>>>> it).
>>>
>>> That makes sense. These packages never really change at all -- the
>>> package version is part of the URI so if it's updated the package URI
>>> changes rather than the data at the old URI. I might set a longer max
>>> age in the config once this is worked out.
>>>
>>>> HTH,
>>>>
>>>> Alex.
>>>>
>>>>
>>>
>>> Thanks.
>>