[squid-users] unexplained MISSes

Fri Oct 10 17:05:26 UTC 2014

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

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

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

iQEcBAEBAgAGBQJUOBHWAAoJELJo5wb/XPRjGv4H/iKpL4UUBOXVsy7BixBeM5xp
JoyRtwRcfH8ksI/G622KANQ2XzOMLyYr9BX5X8ofBGjT8WRRxEbQDzp/EVADB7+6
xO/OwW2413YiYSmgszOTx0joAdUFB4R4ShnCEjDHQ6RJFKIquQql58hDN+6eGHFZ
AkzrlL+V+CzkpOGWmu51kBLlaSMQJ2SaWOJMw0ykn4giuL87XYeRyQ9seFR9Q5Ll
7cKi0QZflcCvDnwa87vPfnvsQfBF/cFjuv7/NigGsO8IklgQ/T3xPf+A6WVXmURj
USLjOmFFsA6xaLZMBeUnmWo4kjX5iYXT1S14yQokpf+DUPfaM0+bt/hUFNLnkuk=
=1TqK
-----END PGP SIGNATURE-----