RE: [squid-users] Re: SSLBump+DynamicSSL not working in Squid 3.2.0.7?

Here is some observation, hope it will be useful solve the problem.

I use curl as the client application. The squid is 3.2.0.7

Curl -x "10.1.19.16:3128" -k https://www.google.com

Tcpdump shown that the CONNECT method is send to ICAP server and a reply is received.
Tcpdump also show that the SSL 1.0 negotiation was done between the squid and curl. The curl verbose output confirms the SSL establishment as well. However, after curl sends the GET to www.google.com through the tunnel, there is no action on the squid site. Searching through the squid log of ALL,9, there is no indication that the squid ever notice the GET request to www.google.com.

Ming

-----Original Message-----
From: Ming Fu [mailto:Ming.Fu_at_watchguard.com]
Sent: Monday, April 25, 2011 3:34 PM
To: Will Metcalf; squid-users_at_squid-cache.org
Subject: RE: [squid-users] Re: SSLBump+DynamicSSL not working in Squid 3.2.0.7?

I experience the same problem for 3.2.0.7 on FreeBSD 8.0.

When https to a site, the CONNECT request is sent for reqmod, but after receiving the reqmod reply, the squid is not proceeding to make the connection to the web server.

Here is the logs with debug option for 93 and 28 on.

2011/04/25 15:19:15.303 kid1| ModXact.cc(696) parseHeaders: parse ICAP headers
2011/04/25 15:19:15.303 kid1| ModXact.cc(1026) parseHead: have 405 head bytes to parse; state: 0
2011/04/25 15:19:15.303 kid1| ModXact.cc(1041) parseHead: parse success, consume 405 bytes, return true
2011/04/25 15:19:15.303 kid1| ModXact.cc(1119) stopParsing: will no longer parse [FD 39;rG/RwP(ieof) job269]
2011/04/25 15:19:15.303 kid1| Adaptation::Icap::ModXact still cannot be repeated because preparing to echo content [FD 39;G/RwP(ieof)rp job269]
2011/04/25 15:19:15.303 kid1| ModXact.cc(667) disableBypass: not protecting group bypass because preparing to echo content
2011/04/25 15:19:15.304 kid1| Xaction.cc(459) setOutcome: ICAP_ECHO
2011/04/25 15:19:15.304 kid1| ModXact.cc(890) prepEchoing: cloning virgin message 0x801fd1800
2011/04/25 15:19:15.304 kid1| ModXact.cc(927) prepEchoing: cloned virgin message 0x801fd1800 to 0x801fd1f00
2011/04/25 15:19:15.304 kid1| ModXact.cc(946) prepEchoing: no virgin body to echo
2011/04/25 15:19:15.304 kid1| ModXact.cc(561) stopSending: Enter stop sending
2011/04/25 15:19:15.304 kid1| ModXact.cc(564) stopSending: Proceed with stop sending
2011/04/25 15:19:15.304 kid1| ModXact.cc(576) stopSending: will not start sending [FD 39;/RwP(ieof)rp job269]
2011/04/25 15:19:15.304 kid1| HttpRequest.cc(428) adaptHistory: made 0x802b1ba40*1 for 0x801fd1f00
2011/04/25 15:19:15.304 kid1| Adaptation::Icap::ModXact still cannot be repeated because sent headers [FD 39;/RwP(ieof)rpS job269]
2011/04/25 15:19:15.304 kid1| Answer.cc(23) Forward: forwarding: 0x801fd1f00
2011/04/25 15:19:15.304 kid1| The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x802b949c0 [call49851]
2011/04/25 15:19:15.304 kid1| Initiate.cc(54) will call Initiator::noteAdaptationAnswer(0) [call49851]
2011/04/25 15:19:15.304 kid1| ModXact.cc(494) readMore: returning from readMore because reader or doneReading()
2011/04/25 15:19:15.304 kid1| Xaction.cc(305) callEnd: Adaptation::Icap::ModXact done with I/O [FD 39;/RwP(ieof)rpS job269]
2011/04/25 15:19:15.304 kid1| Xaction.cc(192) closeConnection: pushing pconn [FD 39;/RwP(ieof)rpS job269]
2011/04/25 15:19:15.304 kid1| Adaptation::Icap::ModXact still cannot be retried [FD 39;/RwP(ieof)rpS job269]
2011/04/25 15:19:15.304 kid1| Adaptation::Icap::Xaction::noteCommRead(FD 39, data=0x801fd1118, size=405, buf=0x802a55000) ends job [/RwP(ieof)rpS job269]
2011/04/25 15:19:15.304 kid1| ModXact.cc(1189) swanSong: swan sings [/RwP(ieof)rpS job269]
2011/04/25 15:19:15.304 kid1| ModXact.cc(561) stopSending: Enter stop sending
2011/04/25 15:19:15.304 kid1| Initiate.cc(36) swanSong: swan sings [/RwP(ieof)rpS job269]
2011/04/25 15:19:15.304 kid1| Initiate.cc(43) swanSong: swan sang [/RwP(ieof)rpS job269]
2011/04/25 15:19:15.304 kid1| Adaptation::Icap::ModXact destructed, this=0x801fd1118 [icapxjob269]
2011/04/25 15:19:15.304 kid1| HttpRequest.cc(67) ~HttpRequest: destructed, this=0x801fd0a00
2011/04/25 15:19:15.304 kid1| AsyncJob destructed, this=0x801fd1728 type=Adaptation::Icap::ModXact [job269]
2011/04/25 15:19:15.304 kid1| AsyncJob.cc(138) callEnd: Adaptation::Icap::Xaction::noteCommRead(FD 39, data=0x801fd1118, size=405, buf=0x802a55000) ended 0x801fd1728
2011/04/25 15:19:15.304 kid1| leaving Adaptation::Icap::Xaction::noteCommRead(FD 39, data=0x801fd1118, size=405, buf=0x802a55000)
2011/04/25 15:19:15.304 kid1| entering Initiator::noteAdaptationAnswer(0)
2011/04/25 15:19:15.304 kid1| AsyncCall.cc(32) make: make call Initiator::noteAdaptationAnswer [call49851]
2011/04/25 15:19:15.304 kid1| Adaptation::Icap::ModXactLauncher status in: [ job268]
2011/04/25 15:19:15.304 kid1| Launcher.cc(56) noteAdaptationAnswer: launches: 1 answer: 0
2011/04/25 15:19:15.304 kid1| The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x802b94c00 [call49854]
2011/04/25 15:19:15.304 kid1| Initiate.cc(54) will call Initiator::noteAdaptationAnswer(0) [call49854]
2011/04/25 15:19:15.304 kid1| Initiator::noteAdaptationAnswer(0) ends job [ job268]
2011/04/25 15:19:15.304 kid1| ModXact.cc(1875) swanSong: swan sings
2011/04/25 15:19:15.304 kid1| Initiate.cc(36) swanSong: swan sings [ job268]
2011/04/25 15:19:15.304 kid1| Initiate.cc(43) swanSong: swan sang [ job268]
2011/04/25 15:19:15.304 kid1| AsyncJob destructed, this=0x8029978b0 type=Adaptation::Icap::ModXactLauncher [job268]
2011/04/25 15:19:15.304 kid1| AsyncJob.cc(138) callEnd: Initiator::noteAdaptationAnswer(0) ended 0x8029978b0
2011/04/25 15:19:15.304 kid1| leaving Initiator::noteAdaptationAnswer(0)
2011/04/25 15:19:15.304 kid1| entering Initiator::noteAdaptationAnswer(0)
2011/04/25 15:19:15.304 kid1| AsyncCall.cc(32) make: make call Initiator::noteAdaptationAnswer [call49854]
2011/04/25 15:19:15.304 kid1| Iterator status in: [ job267]
2011/04/25 15:19:15.304 kid1| ServiceGroups.cc(170) findService: is_pxyscn_req has no matching services
2011/04/25 15:19:15.304 kid1| Iterator.cc(50) step: #2 plan: is_pxyscn_req[1..1.]
2011/04/25 15:19:15.304 kid1| Answer.cc(23) Forward: forwarding: 0x801fd1f00
2011/04/25 15:19:15.304 kid1| The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x802b949c0 [call49855]
2011/04/25 15:19:15.304 kid1| Initiate.cc(54) will call Initiator::noteAdaptationAnswer(0) [call49855]
2011/04/25 15:19:15.304 kid1| Initiator::noteAdaptationAnswer(0) ends job [ job267]
2011/04/25 15:19:15.304 kid1| Initiate.cc(36) swanSong: swan sings [ job267]
2011/04/25 15:19:15.305 kid1| Initiate.cc(43) swanSong: swan sang [ job267]
2011/04/25 15:19:15.305 kid1| AsyncJob destructed, this=0x802997738 type=Iterator [job267]
2011/04/25 15:19:15.305 kid1| AsyncJob.cc(138) callEnd: Initiator::noteAdaptationAnswer(0) ended 0x802997738
2011/04/25 15:19:15.305 kid1| leaving Initiator::noteAdaptationAnswer(0)
2011/04/25 15:19:15.305 kid1| entering Initiator::noteAdaptationAnswer(0)
2011/04/25 15:19:15.305 kid1| AsyncCall.cc(32) make: make call Initiator::noteAdaptationAnswer [call49855]
2011/04/25 15:19:15.305 kid1| ClientHttpRequest status in: [ job265]
2011/04/25 15:19:15.305 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7fffffffe370
2011/04/25 15:19:15.305 kid1| ACLChecklist::~ACLChecklist: destroyed 0x7fffffffe370
2011/04/25 15:19:15.305 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7fffffffe250
2011/04/25 15:19:15.305 kid1| ACLChecklist::~ACLChecklist: destroyed 0x7fffffffe250
2011/04/25 15:19:15.305 kid1| aclCheckFast: list: 0x802b5d3d8
2011/04/25 15:19:15.305 kid1| ACLChecklist::preCheck: 0x7fffffffe0f0 checking 'ssl_bump allow all'
2011/04/25 15:19:15.305 kid1| ACLList::matches: checking all
2011/04/25 15:19:15.305 kid1| ACL::checklistMatches: checking 'all'
2011/04/25 15:19:15.305 kid1| aclIpMatchIp: '10.1.19.14:43996' found
2011/04/25 15:19:15.305 kid1| ACL::ChecklistMatches: result for 'all' is 1
2011/04/25 15:19:15.305 kid1| ACLList::matches: result is true
2011/04/25 15:19:15.305 kid1| aclmatchAclList: 0x7fffffffe0f0 returning true (AND list satisfied)
2011/04/25 15:19:15.305 kid1| ACLChecklist::markFinished: 0x7fffffffe0f0 checklist processing finished
2011/04/25 15:19:15.305 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7fffffffe0f0
2011/04/25 15:19:15.305 kid1| ACLChecklist::~ACLChecklist: destroyed 0x7fffffffe0f0
2011/04/25 15:19:15.305 kid1| ClientHttpRequest status out: [ job265]
2011/04/25 15:19:15.305 kid1| leaving Initiator::noteAdaptationAnswer(0)
2011/04/25 15:19:15.305 kid1| FilledChecklist.cc(95) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x80298f218
2011/04/25 15:19:15.305 kid1| ACLChecklist::~ACLChecklist: destroyed 0x80298f218
2011/04/25 15:19:15.305 kid1| HttpRequest.cc(67) ~HttpRequest: destructed, this=0x801fd1800
2011/04/25 15:19:15.305 kid1| HttpRequest.cc(67) ~HttpRequest: destructed, this=0x801fd1f00
2011/04/25 15:19:15.305 kid1| The AsyncCall Initiate::noteInitiatorAborted constructed, this=0x802ba82b0 [call49857]
2011/04/25 15:19:15.305 kid1| Initiator.cc(28) will call Initiate::noteInitiatorAborted() [call49857]
2011/04/25 15:19:15.305 kid1| AsyncJob destructed, this=0x8020cd7b8 type=ClientHttpRequest [job265]
2011/04/25 15:19:15.305 kid1| entering Initiate::noteInitiatorAborted()
2011/04/25 15:19:15.305 kid1| AsyncCall.cc(32) make: make call Initiate::noteInitiatorAborted [call49857]
2011/04/25 15:19:15.305 kid1| AsyncCall.cc(42) make: will not call Initiate::noteInitiatorAborted [call49857] because of job gone
2011/04/25 15:19:15.305 kid1| leaving Initiate::noteInitiatorAborted()

-----Original Message-----
From: Will Metcalf [mailto:william.metcalf_at_gmail.com]
Sent: Friday, April 22, 2011 12:08 AM
To: squid-users_at_squid-cache.org
Subject: [squid-users] Re: SSLBump+DynamicSSL not working in Squid 3.2.0.7?

Not sure if it helps but here is an access.log entry for a non-working
sslbump+dynamicssl connection.

1303442234.277 0 192.168.1.107 NONE/000 0 CONNECT
gmail.google.com:443 - HIER_NONE/- -

Regards,

Will
On Wed, Apr 20, 2011 at 9:51 PM, Will Metcalf <william.metcalf_at_gmail.com> wrote:
> SSLBump+DynamicSSL was working for me in squid-3.2.0.5-20110329, I
> built and tried 3.2.0.7 last night and it seems to present the spoofed
> cert to the browser but the page never loads.  Can anybody else verify
> this behavior?
>
>  ./configure --datadir=/usr/share/squid3 --sysconfdir=/etc/squid3
> --mandir=/usr/share/man --with-cppunit-basedir=/usr --enable-inline
> --enable-async-io=8 --enable-storeio="ufs,aufs,diskd"
> --enable-removal-policies="lru,heap" --enable-delay-pools
> --enable-cache-digests --enable-underscores --enable-icap-client
> --enable-follow-x-forwarded-for --enable-arp-acl --enable-esi
> --disable-translation --with-logdir=/var/log/squid3
> --with-pidfile=/var/run/squid3.pid --with-filedescriptors=65536
> --with-large-files --with-default-user=proxy --enable-ssl
> --enable-ssl-crtd --enable-ecap && make && sudo make install
>
>
> #relevant portion of the squid.conf that works with squid-3.2.0.5-20110329
> http_port 3128 ssl-bump generate-host-certificates=on
> dynamic_cert_mem_cache_size=4MB
> cert=/usr/local/squid/ssl_cert/will.lan.pem
> sslcrtd_program /usr/local/squid/libexec/ssl_crtd -s
> /usr/local/squid/var/ssl_db -M 4MB
> sslcrtd_children 5
>
> always_direct allow all
> ssl_bump allow all
> sslproxy_cert_error allow all
> sslproxy_flags DONT_VERIFY_PEER
>
Received on Tue Apr 26 2011 - 19:14:37 MDT