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
