Re: [squid-users] Error negotiating SSL connection on FD ##: Closed by client

Right — I hadn’t thought of SNI and what-not. Is there a way I can identify those extensions from Squid’s logs?

I guess if it’s the client closing it, we’re not going to get much info from Squid’s end?

The in-app actions don’t hang per se, it pretty much instantly fails complete but leaves no error about it. In the App Store update case, you press “Update”, the button turns to the spinner for about 1 second and then changes back to the “Update” state as if nothing happened.

This is the cache.log output I get for one of these requests with the afore-mentioned debug_options (access.log has no record of it):

2014/04/07 15:21:55.454 kid1| Checklist.cc(62) preCheck: 0x30a86b8 checking slow rules
2014/04/07 15:21:55.454 kid1| Ip.cc(560) match: aclIpMatchIp: '10.0.1.175:56094' NOT found
2014/04/07 15:21:55.454 kid1| Acl.cc(177) matches: checked: localhost = 0
2014/04/07 15:21:55.454 kid1| Acl.cc(177) matches: checked: (ssl_bump rule) = 0
2014/04/07 15:21:55.454 kid1| Ip.cc(560) match: aclIpMatchIp: '23.73.114.217' NOT found
2014/04/07 15:21:55.454 kid1| Acl.cc(177) matches: checked: bump_bypass = 0
2014/04/07 15:21:55.454 kid1| Acl.cc(177) matches: checked: (ssl_bump rule) = 0
2014/04/07 15:21:55.454 kid1| Ip.cc(560) match: aclIpMatchIp: '10.0.1.175:56094' found
2014/04/07 15:21:55.454 kid1| Acl.cc(177) matches: checked: all = 1
2014/04/07 15:21:55.454 kid1| Acl.cc(177) matches: checked: (ssl_bump rule) = 1
2014/04/07 15:21:55.454 kid1| Acl.cc(177) matches: checked: (ssl_bump rules) = 1
2014/04/07 15:21:55.454 kid1| Checklist.cc(55) markFinished: 0x30a86b8 answer ALLOWED for match
2014/04/07 15:21:55.454 kid1| Checklist.cc(155) checkCallback: ACLChecklist::checkCallback: 0x30a86b8 answer=ALLOWED
2014/04/07 15:21:55.455 kid1| Checklist.cc(62) preCheck: 0x255fe98 checking slow rules
2014/04/07 15:21:55.455 kid1| Ip.cc(560) match: aclIpMatchIp: '23.73.114.217:443' NOT found
2014/04/07 15:21:55.455 kid1| Acl.cc(177) matches: checked: management_interface = 0
2014/04/07 15:21:55.455 kid1| Acl.cc(177) matches: checked: always_direct#1 = 0
2014/04/07 15:21:55.455 kid1| Acl.cc(177) matches: checked: upstream_bypass = 0
2014/04/07 15:21:55.455 kid1| Acl.cc(177) matches: checked: always_direct#2 = 0
2014/04/07 15:21:55.455 kid1| Acl.cc(177) matches: checked: always_direct = 0
2014/04/07 15:21:55.455 kid1| Checklist.cc(378) calcImplicitAnswer: 0x255fe98 NO match found, last action ALLOWED so returning DENIED
2014/04/07 15:21:55.455 kid1| Checklist.cc(55) markFinished: 0x255fe98 answer DENIED for implicit rule won
2014/04/07 15:21:55.455 kid1| Checklist.cc(155) checkCallback: ACLChecklist::checkCallback: 0x255fe98 answer=DENIED
2014/04/07 15:21:56.279 kid1| Checklist.cc(62) preCheck: 0x7fff718578a0 checking fast ACLs
2014/04/07 15:21:56.279 kid1| Acl.cc(177) matches: checked: ssl::certUntrusted = 0
2014/04/07 15:21:56.279 kid1| Acl.cc(177) matches: checked: (sslproxy_cert_sign signUntrusted line) = 0
2014/04/07 15:21:56.279 kid1| Acl.cc(177) matches: checked: sslproxy_cert_sign signUntrusted = 0
2014/04/07 15:21:56.279 kid1| Checklist.cc(55) markFinished: 0x7fff718578a0 answer DENIED for ACLs failed to match
2014/04/07 15:21:56.279 kid1| Checklist.cc(62) preCheck: 0x7fff718578a0 checking fast ACLs
2014/04/07 15:21:56.279 kid1| Acl.cc(177) matches: checked: ssl::certSelfSigned = 0
2014/04/07 15:21:56.279 kid1| Acl.cc(177) matches: checked: (sslproxy_cert_sign signSelf line) = 0
2014/04/07 15:21:56.279 kid1| Acl.cc(177) matches: checked: sslproxy_cert_sign signSelf = 0
2014/04/07 15:21:56.279 kid1| Checklist.cc(55) markFinished: 0x7fff718578a0 answer DENIED for ACLs failed to match
2014/04/07 15:21:56.279 kid1| Checklist.cc(62) preCheck: 0x7fff718578a0 checking fast ACLs
2014/04/07 15:21:56.279 kid1| Ip.cc(560) match: aclIpMatchIp: '10.0.1.175:56094' found
2014/04/07 15:21:56.279 kid1| Acl.cc(177) matches: checked: all = 1
2014/04/07 15:21:56.279 kid1| Acl.cc(177) matches: checked: (sslproxy_cert_sign signTrusted line) = 1
2014/04/07 15:21:56.279 kid1| Acl.cc(177) matches: checked: sslproxy_cert_sign signTrusted = 1
2014/04/07 15:21:56.279 kid1| Checklist.cc(55) markFinished: 0x7fff718578a0 answer ALLOWED for match

On 7 Apr 2014, at 3:10 pm, Amos Jeffries <squid3_at_treenet.co.nz> wrote:

> On 7/04/2014 4:58 p.m., Dan Charlesworth wrote:
>> This somewhat vague error comes up with relative frequency from iOS
>> apps when browsing via our Squid 3.4.4 intercepting proxy which is
>> performing server-first SSL Bumping.
>>
>> The requests in question don’t make it as far as the access log, but
>> with debug_options 28,3 26,3, the dst IP can be identified and
>> allowed through with ssl_bump none.
>
> Aha. So they hang? all requests that start should be logged.
>
>>
>> The device trusts Squid's CA, but apparently that’s not enough for
>> the Twitter iOS app and certain Akamai requests that App Store
>> updates use.
>>
>> Can anyone suggest how one might debug this further? Or just an idea
>> of why the client might be closing the SSL connection in certain
>> cases?
>
> Is there any SNI or NPN or ALPN extensions on those requests?
> It could be the clients are using new non-HTTP protocols whih cannot be
> bumped.
>
>
> Amos
Received on Mon Apr 07 2014 - 05:26:22 MDT