Alex, thanks for the swift response. Your help is very much appreciated! 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.
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 - ORIGINAL_DST/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 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 remote=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 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 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 remote=10.10.1.249:43538 FD 13 flags=33, url=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' 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 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) 2021/01/29 17:31:02.515 kid1| 11,2| client_side.cc(1306) parseHttpRequest: HTTP Client local=52.217.88.134:443 remote=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/1.1 Host: 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 remote=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 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 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 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 remote=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/1.1 User-Agent: curl/7.61.1 Accept: */* Host: 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 remote=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 remote=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 remote=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 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 remote=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 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 remote=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 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 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 remote=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/1.1 User-Agent: squidclient/4.9 Accept: */* Host: 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 remote=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 remote=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 remote=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 remote=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 < rouss...@measurement-factory.com> 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_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> > > > > 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> > > > > 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> in > > reverse DNS lookups. > > > > > > HTH, > > > > Alex. > > > >
_______________________________________________ squid-users mailing list squid-users@lists.squid-cache.org http://lists.squid-cache.org/listinfo/squid-users
