Dear all,
I have some strange misses of cacheable objects. Here is an example (there
are a lot of these objects):
http://www.googletagmanager.com/gtm.js?id=GTM-J5TM
Request (on the client machine):
GET /gtm.js?id=GTM-J5TM HTTP/1.1
Accept: text/html, application/xhtml+xml, */*
Accept-Language: en-US,es-AR;q=0.7,ru;q=0.3
User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; WOW64;
Trident/5.0)
Accept-Encoding: gzip, deflate
Host: www.googletagmanager.com
Connection: Keep-Alive
Response (on the client machine):
HTTP/1.1 200 OK
Content-Type: text/javascript; charset=UTF-8
Content-Encoding: gzip
Vary: Accept-Encoding
Date: Mon, 14 Apr 2014 04:29:21 GMT
Expires: Mon, 14 Apr 2014 04:29:21 GMT
Cache-Control: private, max-age=957
Server: HTTP server (unknown)
Content-Length: 8599
X-XSS-Protection: 1; mode=block
Alternate-Protocol: 80:quic
X-Cache: MISS from squid
Connection: keep-alive
Some log entries with debug_options ALL,1 88,5 85,5 22,5 11,5 for this
request:
2014/04/14 01:29:10.403| client_side_request.cc(1197)
clientInterpretRequestHeaders: clientInterpretRequestHeaders: REQ_NOCACHE =
NOT SET
2014/04/14 01:29:10.403| client_side_request.cc(1199)
clientInterpretRequestHeaders: clientInterpretRequestHeaders: REQ_CACHABLE =
NOT SET
2014/04/14 01:29:10.403| client_side_request.cc(1201)
clientInterpretRequestHeaders: clientInterpretRequestHeaders:
REQ_HIERARCHICAL = NOT SET
2014/04/14 01:29:10.403| client_side_request.cc(137) ~ClientRequestContext:
0x1e51f38 ClientRequestContext destructed
2014/04/14 01:29:10.403| client_side_request.cc(1513) processRequest:
clientProcessRequest: GET
'http://www.googletagmanager.com/gtm.js?id=GTM-J5TM'
2014/04/14 01:29:10.403| client_side_request.cc(1536) httpStart: TAG_NONE
for 'http://www.googletagmanager.com/gtm.js?id=GTM-J5TM'
2014/04/14 01:29:10.403| client_side_reply.cc(1607) identifyFoundObject:
clientProcessRequest2: StoreEntry is NULL - MISS
...
2014/04/14 01:29:10.600| http.cc(919) haveParsedReplyHeaders: HTTP CODE: 200
2014/04/14 01:29:10.600| http.cc(656) httpMakeVaryMark: httpMakeVaryMark:
accept-encoding="gzip,%20deflate"
2014/04/14 01:29:10.601| refresh.cc(247) refreshCheck: refreshCheck:
'http://www.googletagmanager.com/gtm.js?id=GTM-J5TM'
2014/04/14 01:29:10.601| refresh.cc(262) refreshCheck: refreshCheck: Matched
'\.(css|js|gif|bmp|ief|jpeg|jpg|jpe|tiff|tif|ras|pnm|pbm|pgm|ppm|rgb|xbm|xpm
|xwd|png|djv|djvu|wbmp)(\?.*)?$ 258000 80%% 2592000'
2014/04/14 01:29:10.601| refresh.cc(264) refreshCheck: age: 60
2014/04/14 01:29:10.601| refresh.cc(266) refreshCheck: check_time: Mon, 14
Apr 2014 04:30:10 GMT
2014/04/14 01:29:10.601| refresh.cc(268) refreshCheck: entry->timestamp:
Mon, 14 Apr 2014 04:29:10 GMT
2014/04/14 01:29:10.601| refresh.cc(171) refreshStaleness: FRESH: expires
1397450707 >= check_time 1397449810
2014/04/14 01:29:10.601| refresh.cc(288) refreshCheck: Staleness = -1
2014/04/14 01:29:10.601| refresh.cc(373) refreshCheck: refreshCheck: object
isn't stale..
2014/04/14 01:29:10.601| refresh.cc(375) refreshCheck: refreshCheck:
returning FRESH_EXPIRES
2014/04/14 01:29:10.601| http.cc(482) cacheableReply: YES because HTTP
status 200
2014/04/14 01:29:10.601| ctx: exit level 0
2014/04/14 01:29:10.601| client_side_reply.cc(2122) sendMoreData:
clientReplyContext::sendMoreData:
http://www.googletagmanager.com/gtm.js?id=GTM-J5TM, 341 bytes (341 new
bytes)
2014/04/14 01:29:10.601| client_side_reply.cc(2126) sendMoreData:
clientReplyContext::sendMoreData:local=173.194.42.254:80 remote=xx:58387 FD
9 flags=33 'http://www.googletagmanager.com/gtm.js?id=GTM-J5TM' out.offset=0
2014/04/14 01:29:10.601| client_side_reply.cc(1969)
processReplyAccessResult: The reply for GET
http://www.googletagmanager.com/gtm.js?id=GTM-J5TM is ALLOWED, because it
matched 'localnet'
2014/04/14 01:29:10.601| client_side_reply.cc(2007)
processReplyAccessResult: clientReplyContext::sendMoreData: Appending 0
bytes after 341 bytes of headers
2014/04/14 01:29:10.601| client_side.cc(1459) sendStartOfMessage: HTTP
Client local=173.194.42.254:80 remote=xx:58387 FD 9 flags=33
2014/04/14 01:29:10.601| client_side.cc(1460) sendStartOfMessage: HTTP
Client REPLY:
http.cc(482) line says the object is cacheable, nevertheless it's not
cached. If I repeat the same query multiple times, I get the same result.
The important parts of the config are:
http_port 3128 intercept
http_port 3130
cache_dir aufs /var/squid/cache 140000 16 256
maximum_object_size 2 GB
maximum_object_size_in_memory 256 KB
cache_mem 1 GB
cache_replacement_policy heap LFUDA
memory_replacement_policy heap LFUDA
memory_cache_mode always
memory_cache_shared off
cache_swap_low 95
cache_swap_high 96
quick_abort_min -1 KB
ipcache_size 262144
fqdncache_size 262144
via off
httpd_suppress_version_string on
forwarded_for delete
access_log syslog:local3.info squid
cache_log /var/log/squid.log
log_icp_queries off
client_db off
debug_options ALL,1 88,5 85,5 22,5 11,5
# 85,5: StoreEntry is NULL - MISS
# 22,5: refreshCheck
acl localnet src xx/8
acl to_localnet dst xx/8
acl mgr_admin1 src xx
acl ports_local port 3130
acl ports_safe port 80
acl methods_safe method GET POST
acl domains_updates dstdomain .microsoft.com
acl domains_updates dstdomain .windowsupdate.com
acl domains_updates dstdomain .windows.com
acl domains_updates dstdomain .adobe.com
acl domains_updates dstdomain .sun.com
acl url_static url_regex squid-internal-static
http_access allow to_localhost ports_local url_static
http_access allow manager localhost
http_access allow manager mgr_admin1
http_access deny manager
http_access deny !ports_safe
http_access deny !methods_safe
http_access deny to_localhost
http_access deny to_localnet
http_access deny localhost
http_access allow localnet
http_access deny all
range_offset_limit 1 GB domains_updates
refresh_pattern -i
microsoft.com/.*\.(cab|exe|ms[i|u|f]|[ap]sf|wm[v|a]|dat|zip)(\?.*)?$ 4320
80% 43200 override-expire ignore-private ignore-no-cache reload-into-ims
refresh_pattern -i
windowsupdate.com/.*\.(cab|exe|ms[i|u|f]|[ap]sf|wm[v|a]|dat|zip)(\?.*)?$
4320 80% 43200 override-expire ignore-private ignore-no-cache
reload-into-ims
refresh_pattern -i
windows.com/.*\.(cab|exe|ms[i|u|f]|[ap]sf|wm[v|a]|dat|zip)(\?.*)?$ 4320 80%
43200 override-expire ignore-private ignore-no-cache reload-into-ims
refresh_pattern -i
adobe.com/.*\.(cab|exe|ms[i|u|f]|[ap]sf|wm[v|a]|dat|zip)(\?.*)?$ 4320 80%
43200 override-expire ignore-private ignore-no-cache reload-into-ims
refresh_pattern -i
sun.com/.*\.(cab|exe|ms[i|u|f]|[ap]sf|wm[v|a]|dat|zip)(\?.*)?$ 4320 80%
43200 override-expire ignore-private ignore-no-cache reload-into-ims
refresh_pattern -i
\.(css|js|gif|bmp|ief|jpeg|jpg|jpe|tiff|tif|ras|pnm|pbm|pgm|ppm|rgb|xbm|xpm|
xwd|png|djv|djvu|wbmp)(\?.*)?$ 4300 20% 43200 override-expire ignore-private
reload-into-ims
refresh_pattern -i (/cgi-bin/|\?) 0 0% 0
refresh_pattern . 0 20% 4320
------------------------------
Squid version is 3.4.4 (compiled from the source code). The server has 8Gb
RAM without swap, it is supposed that squid will use some 3Gb with the above
config.
This is the squid.log with -d 9 on restart:
Starting Squid Cache version 3.4.4 for x86_64-unknown-linux-gnu...
Process ID 17737
Process Roles: master worker
With 1000000 file descriptors available
Initializing IP Cache...
DNS Socket created at 0.0.0.0, FD 5
Adding nameserver ...
Logfile: opening log syslog:local3.info
Store logging disabled
Swap maxSize 143360000 + 1048576 KB, estimated 11108352 objects
Target number of buckets: 555417
Using 1048576 Store buckets
Max Mem size: 1048576 KB
Max Swap size: 143360000 KB
Rebuilding storage in /var/squid/cache (clean log)
Using Least Load store dir selection
Set Current Directory to /var
Finished loading MIME types and icons.
Squid plugin modules loaded: 0
Accepting NAT intercepted HTTP Socket connections at local=0.0.0.0:3128
remote=[::] FD 8 flags=41
Accepting HTTP Socket connections at local=0.0.0.0:3130 remote=[::] FD 9
flags=9
Store rebuilding is 54.53% complete
Done reading /var/squid/cache swaplog (7335 entries)
Finished rebuilding storage from disk.
7335 Entries scanned
0 Invalid entries.
0 With invalid flags.
7335 Objects loaded.
0 Objects expired.
0 Objects cancelled.
0 Duplicate URLs purged.
0 Swapfile clashes avoided.
Took 0.02 seconds (320683.78 objects/sec).
Beginning Validation Procedure
Completed Validation Procedure
Validated 7335 Entries
store_swap_size = 93148.00 KB
storeLateRelease: released 0 objects
Some other links with very similar request/response headers and squid log
entries are
http://www.googleadservices.com/pagead/conversion_async.js
http://cdn.clicktale.net/www07/ptc/3a4e2875-764c-4dd7-8d30-db51f1744e3e.js
http://cdn.clicktale.net/www/tc/WRe10.js
http://armdl.adobe.com/pub/adobe/reader/win/9.x/9.5.0/en_US/AdbeRdr950_en_US
.exe has the same behavior and was already reported by Marko Cupaæ @ May 15,
2013; 7:17am in "adobe updates constantly re-downloading" mail. Nobody
offered any solution.
refresh.cc(247) refreshCheck: refreshCheck:
'http://armdl.adobe.com/pub/adobe/reader/win/9.x/9.5.0/en_US/AdbeRdr950_en_U
S.exe'
refresh.cc(262) refreshCheck: refreshCheck: Matched
'adobe.com/.*\.(cab|exe|ms[i|u|f]|[ap]sf|wm[v|a]|dat|zip)(\?.*)?$ 259200
80%% 2592000'
refresh.cc(264) refreshCheck: age: 60
refresh.cc(266) refreshCheck: check_time: Mon, 14 Apr 2014 10:21:34 GMT
refresh.cc(268) refreshCheck: entry->timestamp: Mon, 14 Apr 2014
10:20:34 GMT
refresh.cc(207) refreshStaleness: FRESH: age 60 <= stale_age 57447920
refresh.cc(288) refreshCheck: Staleness = -1
refresh.cc(373) refreshCheck: refreshCheck: object isn't stale..
refresh.cc(382) refreshCheck: refreshCheck: returning FRESH_LMFACTOR_RULE
http.cc(482) cacheableReply: YES because HTTP status 200
but..
client_side_reply.cc(1607) identifyFoundObject: clientProcessRequest2:
StoreEntry is NULL - MISS
Please let me know if you know what are the sections for debug_options that
report detailed information about saving objects to the cache (the final
decision-making, the actual store operation, etc.).
Please try these links to confirm it's a common (mis)behavior. Is it a bug
in squid?
Thanks in advance,
Anatoli
Received on Mon Apr 14 2014 - 13:07:45 MDT
This archive was generated by hypermail 2.2.0 : Mon Apr 14 2014 - 12:00:05 MDT