On 1/29/21 6:06 PM, Milos Dodic wrote: > The log is very long :) > I think I found the important part though, but you might need more than > this. No, the snippets you found show an already released cache entry. We still do not know why it was released earlier. > If you need more, could you tell me what to parse for exactly, as I > don't think I can paste the whole log :) Unfortunately, I cannot guess the exact lines to look for -- the true answer may be hidden in many places, and the meaning of many messages depends on their surrounding context. IMO, these low-level debugging logs are only suitable for analysis by capable Squid developers. To save time and effort, I always recommend sharing a link to the compressed log instead. In the past, folks have shared links to DropBox, GitHub gists, Google Drive, and similar temporary upload areas. As always, do not use sensitive data in shared tests and test configurations! Thank you, Alex. > On Fri, Jan 29, 2021 at 8:57 PM Alex Rousskov 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> > > <http://52.217.88.134:443> - ORIGINAL_DST/52.217.88.134 > <http://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> > <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> > <http://52.217.88.134:443> > > remote=10.10.1.249:43538 <http://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> > > <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> > > <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> > > <http://52.217.88.134:443> remote=10.10.1.249:43538 > <http://10.10.1.249:43538> > > <http://10.10.1.249:43538> FD 13 flags=33, url=52.217.88.134:443 > <http://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> > > <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> > <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> > > <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> > > <http://52.217.88.134:443> remote=10.10.1.249:43538 > <http://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://test.XXXXX.com/testFile> HTTP/1.1 > > Host: s3.amazonaws.com <http://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> > > <http://52.217.88.134:443> remote=10.10.1.249:43538 > <http://10.10.1.249:43538> > > <http://10.10.1.249:43538> FD 13 flags=33, > > url=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> > > <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> > <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> > <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> > <http://10.10.0.135:36120> > > remote=52.217.88.134:443 <http://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://test.XXXXX.com/testFile> HTTP/1.1 > > User-Agent: curl/7.61.1 > > Accept: */* > > Host: s3.amazonaws.com <http://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> > <http://10.10.0.135:36120> > > remote=52.217.88.134:443 <http://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> > <http://52.217.88.134:443> > > remote=10.10.1.249:43538 <http://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> > <http://52.217.88.134:443> > > remote=10.10.1.249:43538 <http://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> > <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> > > <http://127.0.0.1:3128> remote=127.0.0.1:50584 > <http://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> > <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> <http://127.0.0.1:3128> > > remote=127.0.0.1:50584 <http://127.0.0.1:50584> > <http://127.0.0.1:50584> FD 13 flags=1, > > url=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> > > <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> > <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> > <http://10.10.0.135:33004> > > remote=52.216.226.131:443 <http://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://test.XXXXX.com/testFile> HTTP/1.1 > > User-Agent: squidclient/4.9 > > Accept: */* > > Host: s3.amazonaws.com <http://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> > <http://10.10.0.135:33004> > > remote=52.216.226.131:443 <http://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> > <http://127.0.0.1:3128> > > remote=127.0.0.1:50584 <http://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> > <http://127.0.0.1:3128> remote=127.0.0.1:50584 <http://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> > <http://127.0.0.1:3128> remote=127.0.0.1:50584 <http://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> > > <mailto: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://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> > > > <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> > > > <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> > > <http://amazonaws.com> in > > > reverse DNS lookups. > > > > > > > > > HTH, > > > > > > Alex. > > > > > > _______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
