Sorry it took me so much time to reply but it seems like either a log bug or something else. I am unsure about it yet. the line in the access.log is: 1373311134.462 38 192.168.10.124 TCP_MISS/304 332 GET http://image.slidesharecdn.com/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 - HIER_DIRECT/88.221.156.163 image/jpeg Which is kind of not real since it's a TCP_MISS but still a 304. If I do a calculation it's like I said before for somebody who asked here. There is a TCP_MISS instead of TCP_IMS/304. There are the ALL,2 cache.log output: ##start 2013/07/08 22:18:54.423 kid1| client_side.cc(2411) parseHttpRequest: HTTP Client local=192.168.10.1:3128 remote=192.168.10.124:41803 FD 54 flags=1 2013/07/08 22:18:54.423 kid1| client_side.cc(2412) parseHttpRequest: HTTP Client REQUEST: --------- GET http://image.slidesharecdn.com/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 HTTP/1.1 Host: image.slidesharecdn.com User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: en-US,en;q=0.5 Accept-Encoding: gzip, deflate Connection: keep-alive If-Modified-Since: Wed, 08 Aug 2012 08:30:54 GMT If-None-Match: "ff40d19dc3187ec5643c7c4a2ffcd0a9" Cache-Control: max-age=0 ---------- 2013/07/08 22:18:54.424 kid1| client_side_request.cc(784) clientAccessCheckDone: The request GET http://image.slidesharecdn.com/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 is ALLOWED, because it matched 'my_net' 2013/07/08 22:18:54.424 kid1| client_side_request.cc(758) clientAccessCheck2: No adapted_http_access configuration. default: ALLOW 2013/07/08 22:18:54.424 kid1| client_side_request.cc(784) clientAccessCheckDone: The request GET http://image.slidesharecdn.com/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 is ALLOWED, because it matched 'my_net' 2013/07/08 22:18:54.425 kid1| forward.cc(124) FwdState: Forwarding client request local=192.168.10.1:3128 remote=192.168.10.124:41803 FD 54 flags=1, url=http://slidesharecdn.squid.internal/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg 2013/07/08 22:18:54.425 kid1| peer_select.cc(269) peerSelectDnsPaths: Find IP destination for: http://slidesharecdn.squid.internal/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg' via image.slidesharecdn.com 2013/07/08 22:18:54.426 kid1| peer_select.cc(290) peerSelectDnsPaths: Found sources for 'http://slidesharecdn.squid.internal/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg' 2013/07/08 22:18:54.426 kid1| peer_select.cc(291) peerSelectDnsPaths: always_direct = DENIED 2013/07/08 22:18:54.426 kid1| peer_select.cc(292) peerSelectDnsPaths: never_direct = DENIED 2013/07/08 22:18:54.426 kid1| peer_select.cc(296) peerSelectDnsPaths: DIRECT = local=0.0.0.0 remote=88.221.156.163:80 flags=1 2013/07/08 22:18:54.426 kid1| peer_select.cc(305) peerSelectDnsPaths: timedout = 0 2013/07/08 22:18:54.426 kid1| http.cc(2198) sendRequest: HTTP Server local=192.168.10.1:46689 remote=88.221.156.163:80 FD 61 flags=1 2013/07/08 22:18:54.426 kid1| http.cc(2199) sendRequest: HTTP Server REQUEST: --------- GET /glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 HTTP/1.1 Host: image.slidesharecdn.com User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: en-US,en;q=0.5 Accept-Encoding: gzip, deflate If-Modified-Since: Wed, 08 Aug 2012 08:30:54 GMT If-None-Match: "ff40d19dc3187ec5643c7c4a2ffcd0a9" Cache-Control: max-age=0 Connection: keep-alive ---------- 2013/07/08 22:18:54.461 kid1| ctx: enter level 0: 'http://slidesharecdn.squid.internal/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg' 2013/07/08 22:18:54.461 kid1| http.cc(749) processReplyHeader: HTTP Server local=192.168.10.1:46689 remote=88.221.156.163:80 FD 61 flags=1 2013/07/08 22:18:54.461 kid1| http.cc(750) processReplyHeader: HTTP Server REPLY: --------- HTTP/1.1 304 Not Modified Content-Type: image/jpeg Last-Modified: Wed, 08 Aug 2012 08:30:54 GMT ETag: "ff40d19dc3187ec5643c7c4a2ffcd0a9" Cache-Control: max-age=31536000 Date: Mon, 08 Jul 2013 19:19:18 GMT Connection: keep-alive Vary: Accept-Encoding ---------- 2013/07/08 22:18:54.461 kid1| ctx: exit level 0 2013/07/08 22:18:54.461 kid1| store.cc(1009) checkCachable: StoreEntry::checkCachable: NO: not cachable 2013/07/08 22:18:54.462 kid1| client_side_reply.cc(1970) processReplyAccessResult: The reply for GET http://image.slidesharecdn.com/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 is ALLOWED, because it matched 'all' 2013/07/08 22:18:54.462 kid1| client_side.cc(1470) sendStartOfMessage: HTTP Client local=192.168.10.1:3128 remote=192.168.10.124:41803 FD 54 flags=1 2013/07/08 22:18:54.462 kid1| client_side.cc(1471) sendStartOfMessage: HTTP Client REPLY: --------- HTTP/1.1 304 Not Modified Content-Type: image/jpeg Last-Modified: Wed, 08 Aug 2012 08:30:54 GMT ETag: "ff40d19dc3187ec5643c7c4a2ffcd0a9" Cache-Control: max-age=31536000 Date: Mon, 08 Jul 2013 19:19:18 GMT Vary: Accept-Encoding X-Cache: MISS from www1.home X-Cache-Lookup: MISS from www1.home:3128 Connection: keep-alive ---------- ##end Which shows that the request is IMS from the client with a ETAG on it. The request is served from local cache rather then from squid cache since the client didn't asked for a response. With basic wget and curl I am getting a full TCP_HIT or TCP_IMS_HIT when doing the same request over and over again. But it seems like the browser is smarter then plain wget and obeys the "rules" of cache and tried to verify the ETAG and Last-Modified. Now the refresh_pattern is: refresh_pattern ^http://slidesharecdn\.squid\.internal/.* 10080 80% 79900 override-expire override-lastmod ignore-no-cache ignore-private ignore-reload ignore-must-revalidate ignore-no-store store-stale ignore-must-revalidate Which I am unsure if squid suppose to actually ignore-no-cache or to convert it to IMS. The next log is when I use firefox and do a full refresh which is using SHIFT+F5 which is not the same as F5 that I have used and have been seen on the logs before: ##start 2013/07/08 22:26:23.157 kid1| client_side.cc(872) swanSong: local=192.168.10.1:3128 remote=192.168.10.124:41829 flags=1 2013/07/08 22:26:23.197 kid1| TcpAcceptor.cc(198) doAccept: New connection on FD 35 2013/07/08 22:26:23.197 kid1| TcpAcceptor.cc(273) acceptNext: connection on local=0.0.0.0:3128 remote=[::] FD 35 flags=9 2013/07/08 22:26:23.198 kid1| client_side.cc(2411) parseHttpRequest: HTTP Client local=192.168.10.1:3128 remote=192.168.10.124:41830 FD 8 flags=1 2013/07/08 22:26:23.198 kid1| client_side.cc(2412) parseHttpRequest: HTTP Client REQUEST: --------- GET http://image.slidesharecdn.com/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 HTTP/1.1 Host: image.slidesharecdn.com User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: en-US,en;q=0.5 Accept-Encoding: gzip, deflate Connection: keep-alive Pragma: no-cache Cache-Control: no-cache ---------- 2013/07/08 22:26:23.198 kid1| client_side_request.cc(784) clientAccessCheckDone: The request GET http://image.slidesharecdn.com/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 is ALLOWED, because it matched 'my_net' 2013/07/08 22:26:23.198 kid1| client_side_request.cc(758) clientAccessCheck2: No adapted_http_access configuration. default: ALLOW 2013/07/08 22:26:23.198 kid1| client_side_request.cc(784) clientAccessCheckDone: The request GET http://image.slidesharecdn.com/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 is ALLOWED, because it matched 'my_net' 2013/07/08 22:26:23.200 kid1| forward.cc(124) FwdState: Forwarding client request local=192.168.10.1:3128 remote=192.168.10.124:41830 FD 8 flags=1, url=http://slidesharecdn.squid.internal/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg 2013/07/08 22:26:23.200 kid1| peer_select.cc(269) peerSelectDnsPaths: Find IP destination for: http://slidesharecdn.squid.internal/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg' via image.slidesharecdn.com 2013/07/08 22:26:23.200 kid1| peer_select.cc(290) peerSelectDnsPaths: Found sources for 'http://slidesharecdn.squid.internal/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg' 2013/07/08 22:26:23.200 kid1| peer_select.cc(291) peerSelectDnsPaths: always_direct = DENIED 2013/07/08 22:26:23.200 kid1| peer_select.cc(292) peerSelectDnsPaths: never_direct = DENIED 2013/07/08 22:26:23.200 kid1| peer_select.cc(296) peerSelectDnsPaths: DIRECT = local=0.0.0.0 remote=88.221.156.163:80 flags=1 2013/07/08 22:26:23.200 kid1| peer_select.cc(305) peerSelectDnsPaths: timedout = 0 2013/07/08 22:26:23.228 kid1| http.cc(2198) sendRequest: HTTP Server local=192.168.10.1:46744 remote=88.221.156.163:80 FD 13 flags=1 2013/07/08 22:26:23.228 kid1| http.cc(2199) sendRequest: HTTP Server REQUEST: --------- GET /glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 HTTP/1.1 Host: image.slidesharecdn.com User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: en-US,en;q=0.5 Accept-Encoding: gzip, deflate Pragma: no-cache Cache-Control: no-cache Connection: keep-alive ---------- 2013/07/08 22:26:23.256 kid1| ctx: enter level 0: 'http://slidesharecdn.squid.internal/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg' 2013/07/08 22:26:23.256 kid1| http.cc(749) processReplyHeader: HTTP Server local=192.168.10.1:46744 remote=88.221.156.163:80 FD 13 flags=1 2013/07/08 22:26:23.256 kid1| http.cc(750) processReplyHeader: HTTP Server REPLY: --------- HTTP/1.1 200 OK x-amz-id-2: rzYdkUpXw11w51eJTKynLasRv3HUjy4d45Kj0a2jj7swoWlpps+p3orjUpgiywdd x-amz-request-id: 959D56498B76D223 Last-Modified: Wed, 08 Aug 2012 08:30:54 GMT x-amz-version-id: gducYyCJ.73GoIA.WcScH1tx7qj9rkby ETag: "ff40d19dc3187ec5643c7c4a2ffcd0a9" Accept-Ranges: bytes Content-Type: image/jpeg Server: AmazonS3 Vary: Accept-Encoding Content-Encoding: gzip Content-Length: 59728 Cache-Control: max-age=31536000 Date: Mon, 08 Jul 2013 19:26:47 GMT Connection: keep-alive � ---------- 2013/07/08 22:26:23.257 kid1| ctx: exit level 0 2013/07/08 22:26:23.257 kid1| client_side_reply.cc(1970) processReplyAccessResult: The reply for GET http://image.slidesharecdn.com/glusterorgwebinarant-120126131226-phpapp01/95/slide-13-728.jpg?1329866994 is ALLOWED, because it matched 'all' 2013/07/08 22:26:23.257 kid1| client_side.cc(1470) sendStartOfMessage: HTTP Client local=192.168.10.1:3128 remote=192.168.10.124:41830 FD 8 flags=1 2013/07/08 22:26:23.257 kid1| client_side.cc(1471) sendStartOfMessage: HTTP Client REPLY: --------- HTTP/1.1 200 OK x-amz-id-2: rzYdkUpXw11w51eJTKynLasRv3HUjy4d45Kj0a2jj7swoWlpps+p3orjUpgiywdd x-amz-request-id: 959D56498B76D223 Last-Modified: Wed, 08 Aug 2012 08:30:54 GMT x-amz-version-id: gducYyCJ.73GoIA.WcScH1tx7qj9rkby ETag: "ff40d19dc3187ec5643c7c4a2ffcd0a9" Accept-Ranges: bytes Content-Type: image/jpeg Server: AmazonS3 Vary: Accept-Encoding Content-Encoding: gzip Content-Length: 59728 Cache-Control: max-age=31536000 Date: Mon, 08 Jul 2013 19:26:47 GMT X-Cache: MISS from www1.home X-Cache-Lookup: MISS from www1.home:3128 Connection: keep-alive ---------- 2013/07/08 22:26:23.258 kid1| store_io.cc(34) storeCreate: storeCreate: Selected dir 0 for -1@-1=0/2/1/1 ##end I am not sure if to think of it as a bug or just as it suppose to be... So we have two cases which are not the same. The first is suppose to be a 304 and is recognized as a 304 but still considered to be a TCP_MISS which is basically a "HIT" and the second case when the request is a no-cache with pragma which suppose to be served from cache or at least to be treated with 304 towards the server and still it stays as a full regular request and then as a TCP_MISS. If there is a need to file a bug just let me know and I will file it with all the details. If not please help me make sure I understood right the logic. Eliezer * a cc to dev-list On 07/04/2013 04:20 AM, Amos Jeffries wrote: > On 4/07/2013 10:13 a.m., Eliezer Croitoru wrote: >> Amos this is one of the weirdest things I have ever seen!! >> the more in depth logs shows a 304 request and response while the >> access log shows 200. > > The cache.log snippets you display below show 200 with the server. > access.log should be showing the status delivered to the client. Where > is the 304 you speak of? > > I woudl expect to see a request from client, a IMS/304 with server and a > 200 or 304 resulting to the client. > >> So I noticed that there is a Pragma header present like this: >> ##start >> 2013/07/04 01:10:16.067 kid1| http.cc(2199) sendRequest: HTTP Server >> REQUEST: >> --------- >> GET >> /rhintrotoglusterfsoct11final-111028123627-phpapp01/95/slide-21-728.jpg?1319823419 >> HTTP/1.1 >> Host: image.slidesharecdn.com >> User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:22.0) Gecko/20100101 >> Firefox/22.0 >> Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 >> Accept-Language: en-US,en;q=0.5 >> Accept-Encoding: gzip, deflate >> Pragma: no-cache >> Cache-Control: no-cache >> Connection: keep-alive > > Pragma should no longer be havig any effect at all for Squid unless > Cache-Control header is completely absent. > > >> >> ---------- >> 2013/07/04 01:10:16.102 kid1| ctx: enter level 0: >> 'http://slidesharecdn.squid.internal/rhintrotoglusterfsoct11final-111028123627-phpapp01/95/slide-21-728.jpg' >> >> 2013/07/04 01:10:16.102 kid1| http.cc(749) processReplyHeader: HTTP >> Server local=192.168.10.1:43176 remote=88.221.156.163:80 FD 13 flags=1 >> 2013/07/04 01:10:16.102 kid1| http.cc(750) processReplyHeader: HTTP >> Server REPLY: >> --------- >> HTTP/1.1 200 OK >> x-amz-id-2: >> boib9MhPcFDoBTAhOtCPIhnJMcp663cUNfLv6JWFcrwRnFdYATNFjpF74A35ZYrq >> x-amz-request-id: A2AB3473F4965692 >> Last-Modified: Tue, 22 May 2012 21:39:08 GMT >> x-amz-version-id: c1_r1OArnftwzoomQNKDfuXd75JYVaEn >> ETag: "b93088a8bb9fdaa382f0755077343b21" >> Accept-Ranges: bytes >> Content-Type: image/jpeg >> Server: AmazonS3 >> Vary: Accept-Encoding >> Content-Encoding: gzip >> Content-Length: 98354 >> Cache-Control: max-age=31536000 >> Date: Wed, 03 Jul 2013 22:10:36 GMT >> Connection: keep-alive > > Server is a bit broken. Sending us "new" content which is well past its > max-age value already. > > >> >> � >> ##END >> >> So actually what can cause this kind of a problem?? >> the 304 is what I would have expected but I see that Pragma effect >> some requests. >> Can we disable Pragma Headers without modifying the request using ICAP? > > Only by removing the Pragma header completely. But 3.3+ should not be > using Pragma unless Cache-Control is completely absent. > > Amos
