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_at_-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
Received on Mon Jul 08 2013 - 19:37:47 MDT
This archive was generated by hypermail 2.2.0 : Tue Jul 09 2013 - 12:00:13 MDT
