[squid-users] unexplained MISSes

Tue Oct 14 04:13:05 UTC 2014

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 12/10/2014 3:36 a.m., Josep Borrell wrote:
> Hi Amos,
> 
> I know that the first request is always a miss. I'm reproducing the
> same vídeo from the same PC, and same browser erasing the cache
> between tests.
> 
> Are there any doc that explain the meaning of all responses like
> ORIGINAL_DST ?

http://wiki.squid-cache.org/SquidFaq/SquidLogs#Hierarchy_Codes

ORIGINAL_DST is when interception is used. It is like DIRECT, but with
transparency in regards to server IP the client is contacting.

Since so many people have confused "interception proxy" with
"transparent proxy" we have enabled transparent request handling by
default whenever interception is performed. You can use the
client_dst_passthru option to turn off server-IP transparency.

> And are there any way to know the reason of a MISS or a HIT ? I
> tried with the debug options, but the reason of a MISS isn't
> there.

The reasons for HIT/MISS are simple; a HIT can only happen if there is
a matching object in cache, REFRESH if there is a stale object in
cache, and MISS if there is no object in cache.

The reasons why (or not) an object is available gets more complicated
and occurs on the *previous* transaction for the same URL. That gets
logic in many different areas having a veto on caching. The main areas
are the store logic and refresh logics. But in particular with
interception the Host security checks also have a large say.

With both interception and store-id acting on the transaction the
story gets even more complicated.
 - you found no mention of forgery detection in your log, so we can
ignore that bit of potential complication.
 - store-id means that not just any previous transaction, but also any
previous transaction(s) sharing the same store-ID will affect the
cache state for this URL.

Amos

> 
> Thanks
> 
> Josep
> 
> 
> -----Mensaje original----- De: squid-users En nombre de Amos
> Jeffries
> 
> On 11/10/2014 5:00 a.m., Josep Borrell wrote:
>> Hi,
> 
>> I'm trying build a squid server that can cache youtube request
>> for a school. I'm using squid 3.4.7 compiled from source on
>> Ubuntu server 14.04 I have a lot of request that are cached, but
>> not served from cache and generate a TCP_MISS/200 I'm trying to
>> figure why this requests are not served from cache. Please find
>> attached squid.conf and cache.log sample with debug enabled.
> 
>> I hope someone can help me.
> 
>> Thanks
> 
>> Josep
> 
>> *************************************************** access.log 
>> *******************************************************************
>
>>  1412953551.775    167 192.168.1.112 TCP_MISS/200 4344 GET 
>> http://i1.ytimg.com/vi/9_iANxI-Mrc/default.jpg - 
>> ORIGINAL_DST/74.125.230.3 image/jpeg
> 
> 
> I see ORIGINAL_DST, meaning you are intercepting users traffic.
> This interception action naturally imposes some big problems which
> Squid has to deal with.
> 
> IF the domain name does not specifically resolve for Squid to the
> same IP the user/client was contacting the object is NOT safely
> cacheable. Squid will therefore not cache it, so as to prevent one
> smart-alec student causing
> http://i1.ytimg.com/vi/9_iANxI-Mrc/default.jpg to be fetched from a
> malware host - thus infecting anyone else loading the "image" they
> get back.
> 
> That required decision by Squid may be part of your problem, or
> not. Check the log file for mentions of "Host header forgery" by
> this clients connection or the previous one(s) fetching that same
> URL.
> 
> NP: if there is *none* previously fetching the URL, there is your
> answer. For it to have become cached someone has to fetch it - the
> first fetch is *always* a MISS.
> 
> 
>> ****************************** cache.log 
>> **********************************************************************
>>
>> 
********************
> 
> 
> ----------
>> 2014/10/10 17:05:51.772| ctx: enter level  0: 
>> 'http://ytimg.com.squid.internal/vi/9_iANxI-Mrc/default.jpg' 
>> 2014/10/10 17:05:51.773| http.cc(705) processReplyHeader: 
>> processReplyHeader: key '9F1BB8D27BED16A8B74F8995105B2941' 
>> 2014/10/10 17:05:51.773| http.cc(749) processReplyHeader: HTTP
>> Server local=192.168.111.10:59210 remote=74.125.230.3:80 FD 65 
>> flags=1 2014/10/10 17:05:51.773| http.cc(750)
>> processReplyHeader: HTTP Server REPLY: --------- HTTP/1.1 200 OK
>> Content-Type: image/jpeg Last-Modified: Thu, 01 Jan 1970 00:23:21
>> GMT Date: Fri, 10 Oct 2014 10:45:51 GMT Expires: Fri, 10 Oct 2014
>> 16:45:51 GMT X-Content-Type-Options: nosniff Server: sffe
>> Content-Length: 3861 X-XSS-Protection: 1; mode=block Age: 15619
>> Cache-Control: public, max-age=21600 Alternate-Protocol:
>> 80:quic,p=0.01
> 
>> ï¿½ï¿½ï¿½ï¿½ ---------- 2014/10/10 17:05:51.773| ctx: exit level 
>> 0 2014/10/10 17:05:51.773| ctx: enter level  0: 
>> 'http://ytimg.com.squid.internal/vi/9_iANxI-Mrc/default.jpg' 
>> 2014/10/10 17:05:51.773| http.cc(919) haveParsedReplyHeaders:
>> HTTP CODE: 200 2014/10/10 17:05:51.773| refresh.cc(247)
>> refreshCheck: refreshCheck: 
>> 'http://ytimg.com.squid.internal/vi/9_iANxI-Mrc/default.jpg' 
>> 2014/10/10 17:05:51.773| refresh.cc(262) refreshCheck: 
>> refreshCheck: Matched '^http:\/\/ytimg\.com\.squid\.internal.* 
>> 604800 80%% 4794000' 2014/10/10 17:05:51.773| refresh.cc(264) 
>> refreshCheck:  age:    15679 2014/10/10 17:05:51.773| 
>> refresh.cc(266) refreshCheck:  check_time:     Fri, 10 Oct 2014 
>> 15:06:51 GMT 2014/10/10 17:05:51.773| refresh.cc(268)
>> refreshCheck: entry->timestamp:       Fri, 10 Oct 2014 10:45:32
>> GMT 2014/10/10 17:05:51.773| refresh.cc(171) refreshStaleness:
>> FRESH: expires 1412959532 >= check_time 1412953611 2014/10/10
>> 17:05:51.773| refresh.cc(288) refreshCheck: Staleness = -1
>> 2014/10/10 17:05:51.773| refresh.cc(373) refreshCheck:
>> refreshCheck: object isn't stale.. 2014/10/10 17:05:51.773|
>> refresh.cc(375) refreshCheck: refreshCheck: returning
>> FRESH_EXPIRES 2014/10/10 17:05:51.773| http.cc(482)
>> cacheableReply: YES because HTTP status 200
> 
> 
> That image is cacheable according to its headers. Provided the next
> client fetches it again within the next 99mins, and the
> interception limits do not prevent storage.
> 
> Check for mentions of "Host header forgery" by this same
> user/client or the previous one fetching this URL.
> 
> 
> 
>> **********************************************************************
>>
>> 
squid.conf *******************************************************
> 
>> # debug helper #debug_options 84,3 #debug Refresh Calculation 
>> #debug_options 22,3 # HTTP #debug_options 11,3
> 
>> debug_options 11,3 22,3 84,3
> 
> 
>> acl customernet src 172.16.212.154/32 acl customernet src 
>> 192.168.1.0/24
> 
> 
>> acl SSL_ports port 443 acl SSL_ports port 873  # rsync
> 
>> acl Safe_ports port 80         # http acl Safe_ports port 21 #
>> ftp acl Safe_ports port 443        # https acl Safe_ports port
>> 70 # gopher acl Safe_ports port 210        # wais acl Safe_ports
>> port 1025-65535 # unregistered ports acl Safe_ports port 280
>> # http-mgmt acl Safe_ports port 488        # gss-http acl
>> Safe_ports port 591        # filemaker acl Safe_ports port 777
>> # multiling http acl CONNECT method CONNECT
> 
>> http_access deny !Safe_ports http_access deny CONNECT !SSL_ports
>>  http_access allow localhost manager http_access deny manager 
>> http_access allow localhost http_access allow customernet
>> http_access deny all # http_access allow all
> 
>> #HTTPS (SSL) trafic interception options always_direct allow
>> SSL_ports ssl_bump server-first SSL_ports #sslproxy_cert_error
>> deny all #sslproxy_flags DONT_VERIFY_PEER sslcrtd_program 
>> /usr/lib/squid3/ssl_crtd -s /var/spool/squid3_ssldb -M 4MB 
>> sslcrtd_children 8 startup=1 idle=1
> 
>> acl rewritedoms dstdomain .c.youtube.com .googlevideo.com
>> .ytimg.com store_id_program /usr/lib/squid3/storeid_file_rewrite 
>> /etc/squid3/storeid_rewrite store_id_children 40 startup=10
>> idle=5 concurrency=0 store_id_access allow rewritedoms
>> store_id_access deny all
> 
> 
>> http_port 3128 http_port 8080 intercept https_port 8081 intercept
>>  ssl-bump generate-host-certificates=on
>> dynamic_cert_mem_cache_size=4MB 
>> cert=/etc/squid3/ssl_cert/squidcert.pem
> 
> 
>> forward_max_tries 25 cache_mem 2 GB
>> maximum_object_size_in_memory 25 MB maximum_object_size 1 GB
> 
>> visible_hostname squid-v2 dns_v4_first on
> 
> 
>> coredump_dir /var/spool/squid3 cache_replacement_policy heap
>> LFUDA cache_dir aufs /var/spool/squid3 14000 16 256
> 
> 14GB of disk trying to cache YT videos may not be enough space.
> 
> If the objects being fetched above were legitimately discarded to
> make room for newer content then MISS is entirely to be expected.
> 
> 
>> refresh_pattern 
>> ^http:\/\/video-srv\.(googlevideo|youtube)\.com\.squid\.internal.*
>>
>> 
10080 80%  79900 override-lastmod override-expire ignore-reload
>> ignore-must-revalidate ignore-private refresh_pattern 
>> ^http:\/\/ytimg\.com\.squid\.internal.*  10080 80%  79900 
>> override-lastmod override-expire ignore-reload
>> ignore-must-revalidate ignore-private
> 
> 
> If you look at those server reply headers you can see the
> Cache-Control explicitly says the reply is "public". This means
> that the "ignore-private" setting is useless on these images. *
> ignoring privacy controls is a highly nasty thing to do to start
> with. I suggest strongly that you remove it from the ytimg pattern
> options as unnecessary.
> 
> Also, here is an artifact of the override options which you may not
> be aware:
> 
> The Expires header coming from YT indicates that the reply is
> cacheable for 6hrs from the time it was generated. That is 21600
> seconds, no less. Your override-expires is actively *reducing* the
> storage time to 10800 seconds (the 'min' field of the pattern
> options).
> 
> Therefore to maximise caching you should *drop* the
> override-expires option on the ytimg pattern.
> 
> 
> NP: override-lastmod is usually also a bad thing to do, but I see
> you are actually hitting THE use-case for which it legitimately
> exist... server emitting incorrect Last-Modified value (1970?
> sure).
> 
> 
> 
> Amos
> 
> _______________________________________________ squid-users mailing
> list squid-users at lists.squid-cache.org 
> http://lists.squid-cache.org/listinfo/squid-users 
> _______________________________________________ squid-users mailing
> list squid-users at lists.squid-cache.org 
> http://lists.squid-cache.org/listinfo/squid-users
> 

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.22 (MingW32)

iQEcBAEBAgAGBQJUPKLRAAoJELJo5wb/XPRjvSIIAKLTnKZa/Vnde559Z+LsXaCP
I50ewcN6yejWKBQECTPbATwnyyyvnhvM0OIj5KoHDOYbAZQZpoEgzf3ID0VppFKn
PLl/2xe3Frs+fxZJxgbUzvgCxvvmk7O5xd5w4Uuks0Rx3dYMo76DFyamKo5hnGXH
4594zS7tWVwhYfsrtw6WeVRifmiw68NjHGsRPve9v0rKTttUGS6WxF+aHK7ZcKQ0
n+eyDdm5bGv1kHqMkhNvmJ4fBk8LoROChpQnQIwp0lm7IJzvi1XwPOk90a/kll4u
lOYRXIeogv7B1DmTNwxThzAi6FknlMZYx3PGdUSU7QTEEQW5kJ1TCdyB9y7Iebo=
=SfGo
-----END PGP SIGNATURE-----