Hi Alex,
The log is very long :)
I think I found the important part though, but you might need more than this.
This is the cache log (ALL,9), that triggered when the server tried to curl a new file, going through Squid:
---------------------------------------------------------------------------------------------------------------------------------------------
2021/01/29 22:48:53.673 kid1| 20,6| Disks.cc(239) get: none of 1 cache_dirs have E577E409BDF0410C8077DCAFF4A234F2
2021/01/29 22:48:53.673 kid1| 20,4| Controller.cc(420) peek: cannot locate E577E409BDF0410C8077DCAFF4A234F2
2021/01/29 22:48:53.673 kid1| 55,9| HttpHeader.cc(956) has: 0x148f118 lookup for Vary[67]
2021/01/29 22:48:53.673 kid1| 20,3| store.cc(456) releaseRequest: 1 e:=p2XIV/0x14a3e80*3
2021/01/29 22:48:53.673 kid1| 11,3| http.cc(982) haveParsedReplyHeaders: decided: do not cache but share because the entry has been released; HTTP status 200 e:=p2XIV/0x14a3e80*3
2021/01/29 22:48:53.673 kid1| 20,4| Controller.cc(420) peek: cannot locate E577E409BDF0410C8077DCAFF4A234F2
2021/01/29 22:48:53.673 kid1| 55,9| HttpHeader.cc(956) has: 0x148f118 lookup for Vary[67]
2021/01/29 22:48:53.673 kid1| 20,3| store.cc(456) releaseRequest: 1 e:=p2XIV/0x14a3e80*3
2021/01/29 22:48:53.673 kid1| 11,3| http.cc(982) haveParsedReplyHeaders: decided: do not cache but share because the entry has been released; HTTP status 200 e:=p2XIV/0x14a3e80*3
and a few lines later
2021/01/29 22:48:53.674 kid1| 20,2| store.cc(986) checkCachable: StoreEntry::checkCachable: NO: not cachable
2021/01/29 22:48:53.674 kid1| 20,3| store_swapout.cc(379) mayStartSwapOut: not cachable
2021/01/29 22:48:53.674 kid1| 20,3| store_swapout.cc(379) mayStartSwapOut: not cachable
---------------------------------------------------------------------------------------------------------------------------------------------
This part "decided: do not cache but share because the entry has been released" could be what we are looking for.
If you need more, could you tell me what to parse for exactly, as I don't think I can paste the whole log :)
And again, thank you very much for helping!
On Fri, Jan 29, 2021 at 8:57 PM Alex Rousskov <rousskov@xxxxxxxxxxxxxxxxxxxxxxx> wrote:
On 1/29/21 12:56 PM, Milos Dodic wrote:
> Here are the logs, but first to mention, from the server that is going
> through the Squid, I am using curl -k (-k to ignore SSL insecure
> warnings atm). From the Squid iself, I use squidclient, as using curl
> from Squid doesn't do much.
It is possible that SslBump (your first/"server" test) side effects
somehow disable caching, but I cannot tell that from the logs you have
shared. IIRC, SslBump does not prevent caching by default.
I see nothing special in the HTTP headers. TLS ServerHello parsing
errors look suspicious, but they happen in both tests, and I suspect
that they are unrelated to the transactions we are talking about -- I
could not quickly tell for sure from the logs you shared.
>> 2021/01/29 17:31:02.537 kid1| 20,2| store.cc(986) checkCachable:
>> StoreEntry::checkCachable: NO: not cachable
If this log entry is about the transaction in question, then it tells us
that Squid marked the response for deletion some time ago. We need to
figure out why Squid is releasing this response. I do not see the answer
in your logs.
Sorry, I cannot offer more help without ALL,9 logs [for the first
transaction in the first/failing test].
HTH,
Alex.
> So when I curl the newly uploaded test file from the server that has
> Squid as default gateway, the access logs shows:
> ------------------------------------------------------------------------------------------------------------------
> 1611941462.501 13 10.10.1.249 NONE/200 0 CONNECT 52.217.88.134:443
> <http://52.217.88.134:443> - ORIGINAL_DST/52.217.88.134
> <http://52.217.88.134> -
> 1611941462.537 22 10.10.1.249 TCP_MISS/200 488 GET
> https://s3.amazonaws.com/test.XXXXX.com/testFile -
> ORIGINAL_DST/52.217.88.134 <http://52.217.88.134> binary/octet-stream
> ------------------------------------------------------------------------------------------------------------------
>
> Cache log is quite long, but won't truncate in order to not omit
> something potentially important:
> --------------------------------------------------------------------------------------------------------------------------------
> 2021/01/29 17:31:02.488 kid1| 5,2| TcpAcceptor.cc(224) doAccept: New
> connection on FD 30
> 2021/01/29 17:31:02.488 kid1| 5,2| TcpAcceptor.cc(312) acceptNext:
> connection on local=[::]:3130 remote=[::] FD 30 flags=41
> 2021/01/29 17:31:02.488 kid1| 33,2| client_side.cc(2748)
> httpsSslBumpAccessCheckDone: sslBump action stareneeded for
> local=52.217.88.134:443 <http://52.217.88.134:443>
> remote=10.10.1.249:43538 <http://10.10.1.249:43538> FD 13 flags=33
> 2021/01/29 17:31:02.488 kid1| 33,2| client_side.cc(3424)
> fakeAConnectRequest: fake a CONNECT request to force connState to tunnel
> for ssl-bump
> 2021/01/29 17:31:02.491 kid1| 85,2| client_side_request.cc(753)
> clientAccessCheckDone: The request CONNECT 52.217.88.134:443
> <http://52.217.88.134:443> is ALLOWED; last ACL checked: allowed_http_sites
> 2021/01/29 17:31:02.492 kid1| 85,2| client_side_request.cc(729)
> clientAccessCheck2: No adapted_http_access configuration. default: ALLOW
> 2021/01/29 17:31:02.492 kid1| 85,2| client_side_request.cc(753)
> clientAccessCheckDone: The request CONNECT 52.217.88.134:443
> <http://52.217.88.134:443> is ALLOWED; last ACL checked: allowed_http_sites
> 2021/01/29 17:31:02.494 kid1| 17,2| FwdState.cc(142) FwdState:
> Forwarding client request local=52.217.88.134:443
> <http://52.217.88.134:443> remote=10.10.1.249:43538
> <http://10.10.1.249:43538> FD 13 flags=33, url="" href="http://52.217.88.134:443" rel="noreferrer" target="_blank">52.217.88.134:443
> <http://52.217.88.134:443>
> 2021/01/29 17:31:02.494 kid1| 44,2| peer_select.cc(302)
> peerSelectDnsPaths: Found sources for '52.217.88.134:443
> <http://52.217.88.134:443>'
> 2021/01/29 17:31:02.494 kid1| 44,2| peer_select.cc(303)
> peerSelectDnsPaths: always_direct = DENIED
> 2021/01/29 17:31:02.494 kid1| 44,2| peer_select.cc(304)
> peerSelectDnsPaths: never_direct = DENIED
> 2021/01/29 17:31:02.494 kid1| 44,2| peer_select.cc(310)
> peerSelectDnsPaths: ORIGINAL_DST = local=0.0.0.0
> remote=52.217.88.134:443 <http://52.217.88.134:443> flags=1
> 2021/01/29 17:31:02.494 kid1| 44,2| peer_select.cc(317)
> peerSelectDnsPaths: timedout = 0
> 2021/01/29 17:31:02.496 kid1| 83,2| bio.cc(316) readAndParse: parsing
> error on FD 15: check failed: state < atHelloReceived
> exception location: Handshake.cc(324) parseHandshakeMessage
>
> 2021/01/29 17:31:02.496 kid1| Error parsing SSL Server Hello Message on
> FD 15
> 2021/01/29 17:31:02.501 kid1| 37,2| IcmpSquid.cc(91) SendEcho: to
> 52.217.88.134, opcode 3, len 13
> 2021/01/29 17:31:02.501| 42,2| IcmpPinger.cc(205) Recv: Pass
> 52.217.88.134 off to ICMPv4 module.
> 2021/01/29 17:31:02.501| 42,2| Icmp.cc(95) Log: pingerLog:
> 1611941462.501640 52.217.88.134 32
> 2021/01/29 17:31:02.501 kid1| 20,2| store.cc(986) checkCachable:
> StoreEntry::checkCachable: NO: not cachable
> 2021/01/29 17:31:02.501 kid1| 20,2| store.cc(986) checkCachable:
> StoreEntry::checkCachable: NO: not cachable
> 2021/01/29 17:31:02.502| 42,2| IcmpPinger.cc(218) SendResult: return
> result to squid. len=7994
> 2021/01/29 17:31:02.502| 42,2| Icmp.cc(95) Log: pingerLog:
> 1611941462.502816 52.217.88.134 0 Echo
> Reply 1ms 6 hops
> 2021/01/29 17:31:02.514 kid1| 83,2| client_side.cc(2683)
> clientNegotiateSSL: New session 0x19d4690 on FD 13 (10.10.1.249:43538
> <http://10.10.1.249:43538>)
> 2021/01/29 17:31:02.515 kid1| 11,2| client_side.cc(1306)
> parseHttpRequest: HTTP Client local=52.217.88.134:443
> <http://52.217.88.134:443> remote=10.10.1.249:43538
> <http://10.10.1.249:43538> FD 13 flags=33
> 2021/01/29 17:31:02.515 kid1| 11,2| client_side.cc(1310)
> parseHttpRequest: HTTP Client REQUEST:
> ---------
> GET /test.XXXXX.com/testFile <http://test.XXXXX.com/testFile> HTTP/1.1
> Host: s3.amazonaws.com <http://s3.amazonaws.com>
> User-Agent: curl/7.61.1
> Accept: */*
>
>
> ----------
> 2021/01/29 17:31:02.520 kid1| 85,2| client_side_request.cc(753)
> clientAccessCheckDone: The request GET
> https://s3.amazonaws.com/test.XXXXX.com/testFile is ALLOWED; last ACL
> checked: allowed_http_sites
> 2021/01/29 17:31:02.520 kid1| 85,2| client_side_request.cc(729)
> clientAccessCheck2: No adapted_http_access configuration. default: ALLOW
> 2021/01/29 17:31:02.520 kid1| 85,2| client_side_request.cc(753)
> clientAccessCheckDone: The request GET
> https://s3.amazonaws.com/test.XXXXX.com/testFile is ALLOWED; last ACL
> checked: allowed_http_sites
> 2021/01/29 17:31:02.520 kid1| 17,2| FwdState.cc(142) FwdState:
> Forwarding client request local=52.217.88.134:443
> <http://52.217.88.134:443> remote=10.10.1.249:43538
> <http://10.10.1.249:43538> FD 13 flags=33,
> url="" href="https://s3.amazonaws.com/test.XXXXX.com/testFile" rel="noreferrer" target="_blank">https://s3.amazonaws.com/test.XXXXX.com/testFile
> 2021/01/29 17:31:02.520 kid1| 44,2| peer_select.cc(281)
> peerSelectDnsPaths: Find IP destination for:
> https://s3.amazonaws.com/test.XXXXX.com/testFile' via s3.amazonaws.com
> <http://s3.amazonaws.com>
> 2021/01/29 17:31:02.520 kid1| 44,2| peer_select.cc(302)
> peerSelectDnsPaths: Found sources for
> 'https://s3.amazonaws.com/test.XXXXX.com/testFile'
> 2021/01/29 17:31:02.520 kid1| 44,2| peer_select.cc(303)
> peerSelectDnsPaths: always_direct = DENIED
> 2021/01/29 17:31:02.520 kid1| 44,2| peer_select.cc(304)
> peerSelectDnsPaths: never_direct = DENIED
> 2021/01/29 17:31:02.520 kid1| 44,2| peer_select.cc(312)
> peerSelectDnsPaths: PINNED = local=0.0.0.0
> remote=52.216.80.75:443 <http://52.216.80.75:443> flags=1
> 2021/01/29 17:31:02.521 kid1| 44,2| peer_select.cc(310)
> peerSelectDnsPaths: ORIGINAL_DST = local=0.0.0.0
> remote=52.217.88.134:443 <http://52.217.88.134:443> flags=1
> 2021/01/29 17:31:02.521 kid1| 44,2| peer_select.cc(317)
> peerSelectDnsPaths: timedout = 0
> 2021/01/29 17:31:02.521 kid1| 37,2| IcmpSquid.cc(91) SendEcho: to
> 52.216.80.75, opcode 3, len 16
> 2021/01/29 17:31:02.521| 42,2| IcmpPinger.cc(205) Recv: Pass
> 52.216.80.75 off to ICMPv4 module.
> 2021/01/29 17:31:02.521| 42,2| Icmp.cc(95) Log: pingerLog:
> 1611941462.521215 52.216.80.75 32
> 2021/01/29 17:31:02.521 kid1| 11,2| http.cc(2260) sendRequest: HTTP
> Server local=10.10.0.135:36120 <http://10.10.0.135:36120>
> remote=52.217.88.134:443 <http://52.217.88.134:443> FD 15 flags=1
> 2021/01/29 17:31:02.521 kid1| 11,2| http.cc(2261) sendRequest: HTTP
> Server REQUEST:
> ---------
> GET /test.XXXXX.com/testFile <http://test.XXXXX.com/testFile> HTTP/1.1
> User-Agent: curl/7.61.1
> Accept: */*
> Host: s3.amazonaws.com <http://s3.amazonaws.com>
> Via: 1.1 squid (squid/4.9)
> X-Forwarded-For: 10.10.1.249
> Cache-Control: max-age=259200
> Connection: keep-alive
>
>
> ----------
> 2021/01/29 17:31:02.521| 42,2| IcmpPinger.cc(218) SendResult: return
> result to squid. len=7997
> 2021/01/29 17:31:02.521| 42,2| Icmp.cc(95) Log: pingerLog:
> 1611941462.521561 52.216.80.75 0 Echo
> Reply 0ms 5 hops
> 2021/01/29 17:31:02.536 kid1| ctx: enter level 0:
> 'https://s3.amazonaws.com/test.XXXXX.com/testFile'
> 2021/01/29 17:31:02.536 kid1| 11,2| http.cc(719) processReplyHeader:
> HTTP Server local=10.10.0.135:36120 <http://10.10.0.135:36120>
> remote=52.217.88.134:443 <http://52.217.88.134:443> FD 15 flags=1
> 2021/01/29 17:31:02.536 kid1| 11,2| http.cc(723) processReplyHeader:
> HTTP Server RESPONSE:
> ---------
> HTTP/1.1 200 OK
> x-amz-id-2:
> hZbtwwRSyeN8TkE+V7V9iUuEEMwyXLVblsFhmazae3kqofWK5EuQf+dH6rU3CF8hDUbj8YcMyw4=
> x-amz-request-id: CD6D86AAA3FDA43F
> Date: Fri, 29 Jan 2021 17:31:03 GMT
> Last-Modified: Fri, 29 Jan 2021 17:27:47 GMT
> ETag: "eb1a3227cdc3fedbaec2fe38bf6c044a"
> Accept-Ranges: bytes
> Content-Type: binary/octet-stream
> Content-Length: 8
> Server: AmazonS3
>
> ----------
> 2021/01/29 17:31:02.536 kid1| ctx: exit level 0
> 2021/01/29 17:31:02.537 kid1| 20,2| store.cc(986) checkCachable:
> StoreEntry::checkCachable: NO: not cachable
> 2021/01/29 17:31:02.537 kid1| 20,2| store.cc(986) checkCachable:
> StoreEntry::checkCachable: NO: not cachable
> 2021/01/29 17:31:02.537 kid1| 88,2| client_side_reply.cc(2061)
> processReplyAccessResult: The reply for GET
> https://s3.amazonaws.com/test.XXXXX.com/testFile is ALLOWED, because it
> matched allowed_http_sites
> 2021/01/29 17:31:02.537 kid1| 11,2| Stream.cc(266) sendStartOfMessage:
> HTTP Client local=52.217.88.134:443 <http://52.217.88.134:443>
> remote=10.10.1.249:43538 <http://10.10.1.249:43538> FD 13 flags=33
> 2021/01/29 17:31:02.537 kid1| 11,2| Stream.cc(267) sendStartOfMessage:
> HTTP Client REPLY:
> ---------
> HTTP/1.1 200 OK
> x-amz-id-2:
> hZbtwwRSyeN8TkE+V7V9iUuEEMwyXLVblsFhmazae3kqofWK5EuQf+dH6rU3CF8hDUbj8YcMyw4=
> x-amz-request-id: CD6D86AAA3FDA43F
> Date: Fri, 29 Jan 2021 17:31:03 GMT
> Last-Modified: Fri, 29 Jan 2021 17:27:47 GMT
> ETag: "eb1a3227cdc3fedbaec2fe38bf6c044a"
> Accept-Ranges: bytes
> Content-Type: binary/octet-stream
> Content-Length: 8
> Server: AmazonS3
> X-Cache: MISS from squid
> X-Cache-Lookup: MISS from squid:3128
> Via: 1.1 squid (squid/4.9)
> Connection: keep-alive
>
>
> ----------
> 2021/01/29 17:31:02.537 kid1| 20,2| store.cc(986) checkCachable:
> StoreEntry::checkCachable: NO: not cachable
> 2021/01/29 17:31:02.537 kid1| 20,2| store.cc(986) checkCachable:
> StoreEntry::checkCachable: NO: not cachable
> 2021/01/29 17:31:02.537 kid1| 20,2| store.cc(986) checkCachable:
> StoreEntry::checkCachable: NO: not cachable
> 2021/01/29 17:31:02.537 kid1| 20,2| store.cc(986) checkCachable:
> StoreEntry::checkCachable: NO: not cachable
> 2021/01/29 17:31:02.538 kid1| 33,2| client_side.cc(582) swanSong:
> local=52.217.88.134:443 <http://52.217.88.134:443>
> remote=10.10.1.249:43538 <http://10.10.1.249:43538> flags=33
> 2021/01/29 17:31:02.538 kid1| 20,2| store.cc(986) checkCachable:
> StoreEntry::checkCachable: NO: not cachable
> --------------------------------------------------------------------------------------------------------------------------------
>
>
>
>
> On the other hand, with squidclient from the Squid itself, access log
> (the first run, when nothing is cached for the new test file yet):
>
> ------------------------------------------------------------------------------------------------------------------
> 1611942152.986 29 127.0.0.1 TCP_MISS/200 483 GET
> https://s3.amazonaws.com/test.dvabearqloza.com/testFile -
> HIER_DIRECT/52.216.226.131 <http://52.216.226.131> binary/octet-stream
> ------------------------------------------------------------------------------------------------------------------
>
> And cache log:
> ------------------------------------------------------------------------------------------------------------------
> 2021/01/29 17:42:32.956 kid1| 5,2| TcpAcceptor.cc(312) acceptNext:
> connection on local=[::]:3128 remote=[::] FD 28 flags=9
> 2021/01/29 17:42:32.957 kid1| 11,2| client_side.cc(1306)
> parseHttpRequest: HTTP Client local=127.0.0.1:3128
> <http://127.0.0.1:3128> remote=127.0.0.1:50584 <http://127.0.0.1:50584>
> FD 13 flags=1
> 2021/01/29 17:42:32.957 kid1| 11,2| client_side.cc(1310)
> parseHttpRequest: HTTP Client REQUEST:
> ---------
> GET https://s3.amazonaws.com/test.XXXXX.com/testFile HTTP/1.0
> Host: s3.amazonaws.com <http://s3.amazonaws.com>
> User-Agent: squidclient/4.9
> Accept: */*
> Connection: close
>
> ----------
> 2021/01/29 17:42:32.957 kid1| 85,2| client_side_request.cc(753)
> clientAccessCheckDone: The request GET
> https://s3.amazonaws.com/test.XXXXX.com/testFile is ALLOWED; last ACL
> checked: allowed_http_sites
> 2021/01/29 17:42:32.957 kid1| 85,2| client_side_request.cc(729)
> clientAccessCheck2: No adapted_http_access configuration. default: ALLOW
> 2021/01/29 17:42:32.957 kid1| 85,2| client_side_request.cc(753)
> clientAccessCheckDone: The request GET
> https://s3.amazonaws.com/test.XXXXX.com/testFile is ALLOWED; last ACL
> checked: allowed_http_sites
> 2021/01/29 17:42:32.957 kid1| 17,2| FwdState.cc(142) FwdState:
> Forwarding client request local=127.0.0.1:3128 <http://127.0.0.1:3128>
> remote=127.0.0.1:50584 <http://127.0.0.1:50584> FD 13 flags=1,
> url="" href="https://s3.amazonaws.com/test.XXXXX.com/testFile" rel="noreferrer" target="_blank">https://s3.amazonaws.com/test.XXXXX.com/testFile
> 2021/01/29 17:42:32.957 kid1| 44,2| peer_select.cc(281)
> peerSelectDnsPaths: Find IP destination for:
> https://s3.amazonaws.com/test.XXXXX.com/testFile' via s3.amazonaws.com
> <http://s3.amazonaws.com>
> 2021/01/29 17:42:32.959 kid1| 44,2| peer_select.cc(302)
> peerSelectDnsPaths: Found sources for
> 'https://s3.amazonaws.com/test.XXXXX.com/testFile'
> 2021/01/29 17:42:32.959 kid1| 44,2| peer_select.cc(303)
> peerSelectDnsPaths: always_direct = DENIED
> 2021/01/29 17:42:32.959 kid1| 44,2| peer_select.cc(304)
> peerSelectDnsPaths: never_direct = DENIED
> 2021/01/29 17:42:32.959 kid1| 44,2| peer_select.cc(308)
> peerSelectDnsPaths: DIRECT = local=0.0.0.0
> remote=52.216.226.131:443 <http://52.216.226.131:443> flags=1
> 2021/01/29 17:42:32.959 kid1| 44,2| peer_select.cc(317)
> peerSelectDnsPaths: timedout = 0
> 2021/01/29 17:42:32.961 kid1| 83,2| bio.cc(316) readAndParse: parsing
> error on FD 15: check failed: state < atHelloReceived
> exception location: Handshake.cc(324) parseHandshakeMessage
>
> 2021/01/29 17:42:32.961 kid1| Error parsing SSL Server Hello Message on
> FD 15
> 2021/01/29 17:42:32.965 kid1| 37,2| IcmpSquid.cc(91) SendEcho: to
> 52.216.226.131, opcode 3, len 16
> 2021/01/29 17:42:32.965| 42,2| IcmpPinger.cc(205) Recv: Pass
> 52.216.226.131 off to ICMPv4 module.
> 2021/01/29 17:42:32.965| 42,2| Icmp.cc(95) Log: pingerLog:
> 1611942152.965403 52.216.226.131 32
> 2021/01/29 17:42:32.965 kid1| 11,2| http.cc(2260) sendRequest: HTTP
> Server local=10.10.0.135:33004 <http://10.10.0.135:33004>
> remote=52.216.226.131:443 <http://52.216.226.131:443> FD 15 flags=1
> 2021/01/29 17:42:32.965 kid1| 11,2| http.cc(2261) sendRequest: HTTP
> Server REQUEST:
> ---------
> GET /test.XXXXX.com/testFile <http://test.XXXXX.com/testFile> HTTP/1.1
> User-Agent: squidclient/4.9
> Accept: */*
> Host: s3.amazonaws.com <http://s3.amazonaws.com>
> Via: 1.0 squid (squid/4.9)
> X-Forwarded-For: 127.0.0.1
> Cache-Control: max-age=259200
> Connection: keep-alive
>
>
> ----------
> 2021/01/29 17:42:32.966| 42,2| IcmpPinger.cc(218) SendResult: return
> result to squid. len=7997
> 2021/01/29 17:42:32.966| 42,2| Icmp.cc(95) Log: pingerLog:
> 1611942152.966514 52.216.226.131 0 Echo
> Reply 1ms 6 hops
> 2021/01/29 17:42:32.985 kid1| ctx: enter level 0:
> 'https://s3.amazonaws.com/test.XXXXX.com/testFile'
> 2021/01/29 17:42:32.985 kid1| 11,2| http.cc(719) processReplyHeader:
> HTTP Server local=10.10.0.135:33004 <http://10.10.0.135:33004>
> remote=52.216.226.131:443 <http://52.216.226.131:443> FD 15 flags=1
> 2021/01/29 17:42:32.985 kid1| 11,2| http.cc(723) processReplyHeader:
> HTTP Server RESPONSE:
> ---------
> HTTP/1.1 200 OK
> x-amz-id-2:
> z//C9o0g1wI5ep44MaSBbU7ptfDlvOjTZLIBYSpaI8+h8oxt607nyA9zumm8eEk+wTJb3jRD7wU=
> x-amz-request-id: A6E14CC59FE63894
> Date: Fri, 29 Jan 2021 17:42:33 GMT
> Last-Modified: Fri, 29 Jan 2021 17:27:47 GMT
> ETag: "eb1a3227cdc3fedbaec2fe38bf6c044a"
> Accept-Ranges: bytes
> Content-Type: binary/octet-stream
> Content-Length: 8
> Server: AmazonS3
>
> ----------
> 2021/01/29 17:42:32.986 kid1| ctx: exit level 0
> 2021/01/29 17:42:32.986 kid1| 88,2| client_side_reply.cc(2061)
> processReplyAccessResult: The reply for GET
> https://s3.amazonaws.com/test.XXXXX.com/testFile is ALLOWED, because it
> matched allowed_http_sites
> 2021/01/29 17:42:32.986 kid1| 11,2| Stream.cc(266) sendStartOfMessage:
> HTTP Client local=127.0.0.1:3128 <http://127.0.0.1:3128>
> remote=127.0.0.1:50584 <http://127.0.0.1:50584> FD 13 flags=1
> 2021/01/29 17:42:32.986 kid1| 11,2| Stream.cc(267) sendStartOfMessage:
> HTTP Client REPLY:
> ---------
> HTTP/1.1 200 OK
> x-amz-id-2:
> z//C9o0g1wI5ep44MaSBbU7ptfDlvOjTZLIBYSpaI8+h8oxt607nyA9zumm8eEk+wTJb3jRD7wU=
> x-amz-request-id: A6E14CC59FE63894
> Date: Fri, 29 Jan 2021 17:42:33 GMT
> Last-Modified: Fri, 29 Jan 2021 17:27:47 GMT
> ETag: "eb1a3227cdc3fedbaec2fe38bf6c044a"
> Accept-Ranges: bytes
> Content-Type: binary/octet-stream
> Content-Length: 8
> Server: AmazonS3
> X-Cache: MISS from squid
> X-Cache-Lookup: MISS from squid:3128
> Via: 1.1 squid (squid/4.9)
> Connection: close
>
>
> ----------
> 2021/01/29 17:42:32.986 kid1| 20,2| store_io.cc(43) storeCreate:
> storeCreate: Selected dir 0 for e:=sp2V/0x1f582b0*4
> 2021/01/29 17:42:32.986 kid1| 33,2| client_side.cc(891) kick:
> local=127.0.0.1:3128 <http://127.0.0.1:3128> remote=127.0.0.1:50584
> <http://127.0.0.1:50584> flags=1 Connection was closed
> 2021/01/29 17:42:32.986 kid1| 33,2| client_side.cc(582) swanSong:
> local=127.0.0.1:3128 <http://127.0.0.1:3128> remote=127.0.0.1:50584
> <http://127.0.0.1:50584> flags=1
> ------------------------------------------------------------------------------------------------------------------
>
> The first thing that caught my attention was the line:
> "checkCachable: StoreEntry::checkCachable: NO: not cachable", that
> appears in the logs when server tries to go through proxy.
>
> Any idea what might be the issue overall?
>
> Thanks again!!!
>
>
>
>
> On Fri, Jan 29, 2021 at 5:40 PM Alex Rousskov
> <rousskov@xxxxxxxxxxxxxxxxxxxxxxx
> <mailto:rousskov@xxxxxxxxxxxxxxxxxxxxxxx>> wrote:
>
> On 1/28/21 1:34 PM, Milos Dodic wrote:
>
> > I have noticed that the test server also doesn't cache anything
> > So if I try to go for a file in S3, it says MISS, and after that, MISS
> > again, and I see no new objects in cache being created.
>
> > If I try the same thing from the proxy itself, I get the MISS, and the
> > object gets cached, as it should.
> > When I go back to the test server, and try again, it sees the
> object in
> > cache and returns TCP_MEM_HIT/200 instead.
>
> Without more details, I can only speculate that the client running on
> the test server sends different HTTP request headers than the client
> running on the proxy itself. You can see the headers in cache.log if you
> set debug_options to ALL,2. If you are not sure whether they are the
> same, please share those logs. They will also contain response headers
> and other potentially useful details.
>
> If the request headers are the same in both tests, then I would
> recommend sharing compressed ALL,7 or ALL,9 debugging logs of both
> successful and unsuccessful tests (four transactions, two logs) for
> analysis. Do not use sensitive data for these tests.
>
> https://wiki.squid-cache.org/SquidFaq/BugReporting#Debugging_a_single_transaction
>
> Alex.
>
>
>
> > This is the entire config file:
> >
> >
> > visible_hostname squid
> > cache_dir ufs /test/cache/squid 10000 16 256
> >
> > http_access allow localhost
> > http_access alow all
> >
> > http_port 3128
> > http_port 3129 intercept
> > acl allowed_http_sites dstdomain .amazonaws.com
> <http://amazonaws.com> <http://amazonaws.com>
> > http_access allow allowed_http_sites
> >
> > https_port 3130 cert=/etc/squid/ssl/squid.pem ssl-bump intercept
> > acl SSL_port port 443
> > http_access allow SSL_port
> > acl allowed_https_sites ssl::server_name .amazonaws.com
> <http://amazonaws.com>
> > <http://amazonaws.com>
> >
> > ssl_bump stare all
> > ssl_bump bump allowed_https_sites
> > ssl_bump terminate all
>
>
> > On Tue, Jan 26, 2021 at 9:14 PM Alex Rousskov wrote:
> >
> > On 1/26/21 1:54 PM, Milos Dodic wrote:
> >
> > > when the test server goes for a picture I have stored
> somewhere in
> > > the cloud, the squid access log shows "TCP_TUNNEL/200". But
> when I
> > > try from the proxy itself with squidclient tool, I get
> > > "TCP_MEM_HIT/200"
> >
> >
> > Given the very limited information you have provided, I am
> guessing that
> >
> > * the primary tests opens a CONNECT tunnel through Squid
> > * the squidclient test sends a plain text HTTP request to Squid
> >
> > The final origin server destination may be the same in both
> tests, but
> > the two transactions are completely different from Squid point
> of view.
> >
> >
> > > ssl_bump peek step1 all
> > > ssl_bump peek step2 allowed_https_sites
> > > ssl_bump splice step3 allowed_https_sites
> > > ssl_bump terminate step3 all
> >
> >
> > AFAICT, this configuration is splicing or terminating all TLS
> traffic.
> > No bumping at all. If you want your Squid to bump TLS tunnels,
> then you
> > have to have at least one "bump" rule!
> >
> > I do not know what your overall SslBump needs are, but perhaps
> you meant
> > something like the following?
> >
> > acl shouldBeBumped ssl::server_name .amazonaws.com
> <http://amazonaws.com>
> > <http://amazonaws.com>
> >
> > ssl_bump stare all
> > ssl_bump bump shouldBeBumped
> > ssl_bump terminate all
> >
> > Please do not use the configuration above until you understand
> what it
> > does. Please see
> https://wiki.squid-cache.org/Features/SslPeekAndSplice
> > for details.
> >
> > Depending on your environment, the http_access rules may need
> to be
> > adjusted to allow CONNECT requests (to TLS-safe ports) to IP
> addresses
> > that do not result in .amazonaws.com <http://amazonaws.com>
> <http://amazonaws.com> in
> > reverse DNS lookups.
> >
> >
> > HTH,
> >
> > Alex.
> >
>
_______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
