Fixing Squid configuration for caching proxy?

classic Classic list List threaded Threaded
10 messages Options
Reply | Threaded
Open this post in threaded view
|

Fixing Squid configuration for caching proxy?

Milos Dodic

I am trying to have a setup where Squid is going to act as a transparent forward proxy, with caching enabled. I am leaning on a setup like here: https://aws.amazon.com/blogs/security/how-to-add-dns-filtering-to-your-nat-instance-with-squid/ (though I've tried a few similar ones as well).

The requirement is to have a transparent caching proxy on AWS, that will be used to reduce the traffic that is being pulled from a remote company (the data is being pulled on a schedule, while there are not many changes that often). This traffic causes additional cost, and caching that on our proxy on AWS could help us out a lot.


The issue I have is, when I configure everything, the test server that is going through proxy is not actually caching anything, while if I try a test from the proxy itself (using squidclient) it does. So 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" (the first time it was MISS, before it was cached), so caching works properly - I even see the new folder being created or the cached content.

I have the rerouting rules added to IP tables, source and destination check is disabled (AWS setup), and overall, traffic is going as it should. I assume I need to make some changes in the configuration, as that part is where I had to copy most of the stuff, and have least experience with. I've generated the certificate as per the doc, and my config is mostly the same as the one there:

(note, I have tried with multiple changes to this config, without success)

visible_hostname squid
cache_dir ufs /squid/cache 10000 16 256

# Handle HTTP requests
http_port 3128
http_port 3129 intercept
acl allowed_http_sites dstdomain .amazonaws.com
http_access allow allowed_http_sites

# Handle HTTPS requests
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
acl step1 at_step SslBump1
acl step2 at_step SslBump2
acl step3 at_step SslBump3
ssl_bump peek step1 all
ssl_bump peek step2 allowed_https_sites
ssl_bump splice step3 allowed_https_sites
ssl_bump terminate step3 all

http_access deny all


The cert and everything else is generated as per the guide (and a few guides are very similar here when it comes to this part).
The whitelisting works, mostly everything else works too, so the only thing missing is squid not caching things that are requested by the test server and is instead only passing it through. Any idea what configuration changes I need in order to fix this? I guess I am doing something wrong with ssl bump.

Thanks!


_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Fixing Squid configuration for caching proxy?

Alex Rousskov
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

    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 in reverse DNS lookups.


HTH,

Alex.
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Fixing Squid configuration for caching proxy?

Milos Dodic
I have redeployed everything, with most basic configuration, and use the proposed config for ssl_bump.
The test server that goes through Squid now doesn't get tunneled, and instead checks the cache. I get something like this
NONE/200
TCP_MISS/200

But I have noticed that the test server also doesn't cache anything, and instead only looks at the cache.
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.

Is there a specific configuration that I need to add/enable, in order to have the server cache the objects, or am I making a mistake elsewhere perhaps?
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_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

ssl_bump stare all
ssl_bump bump allowed_https_sites
ssl_bump terminate all




Thanks!

On Tue, Jan 26, 2021 at 9:14 PM Alex Rousskov <[hidden email]> 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

    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 in reverse DNS lookups.


HTH,

Alex.

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Fixing Squid configuration for caching proxy?

Alex Rousskov
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
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Fixing Squid configuration for caching proxy?

Milos Dodic
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 <[hidden email]> 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
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Fixing Squid configuration for caching proxy?

Alex Rousskov
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=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=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=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
> <[hidden email]
> <mailto:[hidden email]>> 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
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Fixing Squid configuration for caching proxy?

Milos Dodic
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

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
---------------------------------------------------------------------------------------------------------------------------------------------

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 <[hidden email]> 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=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=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=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
> <[hidden email]
> <mailto:[hidden email]>> 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
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Fixing Squid configuration for caching proxy?

Alex Rousskov
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
>     > <[hidden email]
>     <mailto:[hidden email]>
>     > <mailto:[hidden email]
>     <mailto:[hidden email]>>> 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
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Fixing Squid configuration for caching proxy?

Amos Jeffries
Administrator
In reply to this post by Alex Rousskov
On 30/01/21 8:57 am, 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 expect the lack of caching is due to the first "request" being
intercepted port 443 traffic. The second is a forward proxy https://
request.


Amos
_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users
Reply | Threaded
Open this post in threaded view
|

Re: Fixing Squid configuration for caching proxy?

Eliezer Croitoru-3
In reply to this post by Milos Dodic
Hey Milos,

I suggest to try and test this against:
http://s3.amazonaws.com/awsdocs/S3/latest/s3-gsg.pdf
http://s3.amazonaws.com/awsdocs/gettingstarted/latest/awsgsg-freetier.pdf

https://s3.amazonaws.com/awsdocs/gettingstarted/latest/awsgsg-freetier.pdf
https://s3.amazonaws.com/awsdocs/S3/latest/s3-gsg.pdf

What version of squid are you using?
squid -v
output should give something.

Eliezer

----
Eliezer Croitoru
Tech Support
Mobile: +972-5-28704261
Email: mailto:[hidden email]
Zoom: Coming soon


From: squid-users <[hidden email]> On Behalf Of Milos Dodic
Sent: Friday, January 29, 2021 7:57 PM
To: Alex Rousskov <[hidden email]>
Cc: [hidden email]
Subject: Re: [squid-users] Fixing Squid configuration for caching proxy?

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 http://52.217.88.134:443 - ORIGINAL_DST/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/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=http://52.217.88.134:443 remote=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 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 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=http://52.217.88.134:443 remote=http://10.10.1.249:43538 FD 13 flags=33, url=http://52.217.88.134:443
2021/01/29 17:31:02.494 kid1| 44,2| peer_select.cc(302) peerSelectDnsPaths: Found sources for '<a href="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=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 (http://10.10.1.249:43538)
2021/01/29 17:31:02.515 kid1| 11,2| client_side.cc(1306) parseHttpRequest: HTTP Client local=http://52.217.88.134:443 remote=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 /http://test.XXXXX.com/testFile HTTP/1.1
Host: 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=http://52.217.88.134:443 remote=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 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=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=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=http://10.10.0.135:36120 remote=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 /http://test.XXXXX.com/testFile HTTP/1.1
User-Agent: curl/7.61.1
Accept: */*
Host: 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=http://10.10.0.135:36120 remote=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=http://52.217.88.134:443 remote=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=http://52.217.88.134:443 remote=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/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=http://127.0.0.1:3128 remote=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: 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=http://127.0.0.1:3128 remote=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 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=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=http://10.10.0.135:33004 remote=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 /http://test.XXXXX.com/testFile HTTP/1.1
User-Agent: squidclient/4.9
Accept: */*
Host: 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=http://10.10.0.135:33004 remote=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=http://127.0.0.1:3128 remote=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=http://127.0.0.1:3128 remote=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=http://127.0.0.1:3128 remote=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 <mailto:[hidden email]> 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 .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 .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 .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 .http://amazonaws.com <http://amazonaws.com> in
>     reverse DNS lookups.
>
>
>     HTH,
>
>     Alex.
>

_______________________________________________
squid-users mailing list
[hidden email]
http://lists.squid-cache.org/listinfo/squid-users