On 7/03/2013 10:54 p.m., Amm wrote:
----- Original Message -----
From: Amos Jeffries <squ...@treenet.co.nz>
To: squid-users@squid-cache.org
Cc:
Sent: Thursday, 7 March 2013 1:11 PM
Subject: Re: [squid-users] Bypassing SSL Bump for dstdomain
On 7/03/2013 7:22 p.m., Amm wrote:
<snip>
For testing, URL was accessed with curl (curl -k https://www.google.com/)
Here is debug output: (Google IP has changed but in same subnet, 1.2.3.4 is
my public IP replaced)
2013/03/07 11:40:46.326 kid1| client_side.cc(2325) parseHttpRequest: HTTP
Client local=173.194.36.18:443 remote=1.2.3.4:50145 FD 21 flags=33
2013/03/07 11:40:46.326 kid1| client_side.cc(2326) parseHttpRequest: HTTP
Client REQUEST:
---------
GET / HTTP/1.1
User-Agent: curl/7.21.7 (x86_64-redhat-linux-gnu) libcurl/7.21.7
NSS/3.13.5.0 zlib/1.2.5 libidn/1.22 libssh2/1.2.7
Host: www.google.com
Accept: */*
----------
2013/03/07 11:40:46.326 kid1| http.cc(2177) sendRequest: HTTP Server
local=1.2.3.4:50146 remote=173.194.36.18:443 FD 23 flags=1
2013/03/07 11:40:46.326 kid1| http.cc(2178) sendRequest: HTTP Server
REQUEST:
---------
GET / HTTP/1.1
User-Agent: curl/7.21.7 (x86_64-redhat-linux-gnu) libcurl/7.21.7
NSS/3.13.5.0 zlib/1.2.5 libidn/1.22 libssh2/1.2.7
Host: www.google.com
Accept: */*
Via: 1.1 a.b.c (squid/3.3.2)
X-Forwarded-For: 1.2.3.4
Cache-Control: max-age=259200
Connection: keep-alive
HTTP server REQUEST shows 173.194.36.18, but access.logs show IPv6 address:
1362636646.416 90 1.2.3.4 TCP_MISS/302 1138 GET https://www.google.com/
- PINNED/2404:6800:4009:802::1011 text/html
This is a really *really* strange outcome. It is indeed looking like a
code bug somewhere.
The cache.log showed the TCP level details being apparently correct. So
I think we can ignore everyting up to the point of logging.
Just to cofirm that can you add the server response trace from that
server request? It will be a short while later with identical local=
remote= and FD values.
If there is anything else on that FD 23 it would be useful to know as well.
2013/03/07 11:40:46.416 kid1| ctx: enter level 0: 'https://www.google.com/'
2013/03/07 11:40:46.416 kid1| http.cc(746) processReplyHeader: HTTP Server
local=1.2.3.4:50146 remote=173.194.36.18:443 FD 23 flags=1
2013/03/07 11:40:46.416 kid1| http.cc(747) processReplyHeader: HTTP Server
REPLY:
---------
HTTP/1.1 302 Found
Location: https://www.google.co.in/
Cache-Control: private
Content-Type: text/html; charset=UTF-8
Set-Cookie: XXXXX
Set-Cookie: XXXXX
P3P: CP="This is not a P3P policy! See
http://www.google.com/support/accounts/bin/answer.py?hl=en&answer=151657 for more
info."
Date: Thu, 07 Mar 2013 06:10:46 GMT
Server: gws
Content-Length: 222
X-XSS-Protection: 1; mode=block
X-Frame-Options: SAMEORIGIN
<HTML><HEAD><meta http-equiv="content-type" content="text/html;charset=utf-8">
<TITLE>302 Moved</TITLE></HEAD><BODY>
<H1>302 Moved</H1>
The document has moved
<A HREF="https://www.google.co.in/";>here</A>.
</BODY></HTML>
----------
2013/03/07 11:40:46.416 kid1| ctx: exit level 0
2013/03/07 11:40:46.416 kid1| client_side.cc(1386) sendStartOfMessage: HTTP
Client local=173.194.36.18:443 remote=1.2.3.4:50145 FD 21 flags=33
2013/03/07 11:40:46.416 kid1| client_side.cc(1387) sendStartOfMessage: HTTP
Client REPLY:
---------
HTTP/1.1 302 Moved Temporarily
Location: https://www.google.co.in/
Cache-Control: private
Content-Type: text/html; charset=UTF-8
Set-Cookie: XXXXX
Set-Cookie: XXXXX
P3P: CP="This is not a P3P policy! See
http://www.google.com/support/accounts/bin/answer.py?hl=en&answer=151657 for more
info."
Date: Thu, 07 Mar 2013 06:10:46 GMT
Server: gws
Content-Length: 222
X-XSS-Protection: 1; mode=block
X-Frame-Options: SAMEORIGIN
X-Cache: MISS from a.b.c
X-Cache-Lookup: MISS from a.b.c:8080
Via: 1.1 a.b.c (squid/3.3.2)
Connection: keep-alive
If we assume there is someting terribly broken with where the access.log
data is being generate from.
Can you create a custom log format please which outputs:
logformat test %>A/%>a:%>p -> %>la:%>lp (%la:%lp)
%<la:%<lp ->
%<A/%<a:%<p [%h{Host}]
and use it for a secondary access_log line. Lets see what gets logged by
that.
[%h{Host}] was giving error, so i changed it to [%{Host}>h]
Here is output:
ABCD.net.in/1.2.3.4:33307 -> 173.194.36.16:443 (-:8081) :::0 ->
www.google.com/2404:6800:4009:802::1011:443 [www.google.com]
Notice :::0 - somewhere it thinks its IPv6??
If domain has just IPv4 address and no IPv6 address:
ABCD.net.in/1.2.3.4:58347 -> 174.122.92.66:443 (-:8081) 0.0.0.0:0 ->
www.bigrock.com/174.122.92.65:443 [www.bigrock.com]
If i use dns_v4_first, it logs IPv4 address.
ABCD.mtnl.net.in/1.2.3.4:33559
-> 74.125.236.147:443 (-:8081) 0.0.0.0:0 ->
www.google.com/74.125.236.146:443 [www.google.com]
Notice the change in IP address though. But may be that is expected as squid
does its own DNS lookup and picks other IP.
Okay that zero IP:port on the outbound confirmed my suspicion about what
the code was doing. When using a pinned connection it is not setting the
real connection details into the log.
If it is still logging the IPv6. I have an experimental patch here:
http://master.squid-cache.org/~amosjeffries/patches/pinning_hier_note.patch
If you could apply that and see what the above log changes to it would
be great.
Cheers
Amos
Applying and trying patch will take about a day. Will let you know once I do.
Thanks.
The above log entry implies it should be the fix, but I will still need
confirmation of that.
Amos
