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