[squid-users] Kerberos negotiate slow avg service time

Wed Feb 28 00:50:29 UTC 2018

On 28/02/18 07:43, erdosain9 wrote:
> Thank you Amos (sorry again Yuri).
> 
> And yes, the user are complains.
> 
> The problem is this (and sorry for be recurrent with this).
> 
> That value avg ms for some times goes up to 3000... and in that moment all
> stop.
> 
> in the cache.log sometimes, im getting this.
> 
> support_sasl.cc(276): pid=3729 :2018/02/27 14:44:35| kerberos_ldap_group:
> ERROR: ldap_sasl_interactive_bind_s error: Can't contact LDAP server
> support_ldap.cc(957): pid=3729 :2018/02/27 14:44:35| kerberos_ldap_group:
> ERROR: Error while binding to ldap server with SASL/GSSAPI: Can't contact
> LDAP server
> 2018/02/27 14:44:49 kid1| Error negotiating SSL on FD 45:
> error:00000000:lib(0):func(0):reason(0) (5/-1/104)
> support_sasl.cc(276): pid=3719 :2018/02/27 14:46:56| kerberos_ldap_group:
> ERROR: ldap_sasl_interactive_bind_s error: Can't contact LDAP server
> support_ldap.cc(957): pid=3719 :2018/02/27 14:46:56| kerberos_ldap_group:
> ERROR: Error while binding to ldap server with SASL/GSSAPI: Can't contact
> LDAP server
> support_sasl.cc(276): pid=3719 :2018/02/27 14:47:18| kerberos_ldap_group:
> ERROR: ldap_sasl_interactive_bind_s error: Can't contact LDAP server
> support_ldap.cc(957): pid=3719 :2018/02/27 14:47:18| kerberos_ldap_group:
> ERROR: Error while binding to ldap server with SASL/GSSAPI: Can't contact
> LDAP server
> support_sasl.cc(276): pid=3729 :2018/02/27 14:47:28| kerberos_ldap_group:
> ERROR: ldap_sasl_interactive_bind_s error: Can't contact LDAP server
> support_ldap.cc(957): pid=3729 :2018/02/27 14:47:28| kerberos_ldap_group:
> ERROR: Error while binding to ldap server with SASL/GSSAPI: Can't contact
> LDAP server
> support_sasl.cc(276): pid=3719 :2018/02/27 14:47:36| kerberos_ldap_group:
> ERROR: ldap_sasl_interactive_bind_s error: Can't contact LDAP server
> support_ldap.cc(957): pid=3719 :2018/02/27 14:47:36| kerberos_ldap_group:
> ERROR: Error while binding to ldap server with SASL/GSSAPI: Can't contact
> LDAP server
> 
> 
> Is impossible that this problem happend from the squid side? Im thinking
> that is a problem in the AD (windows server 2012).

The Squid helper is using a SASL library on your system to contact the
LDAP server. Those error messages are sadly all the info which Squid or
its helper have about the failure.

A quick search for the message though, brings up this document about
LDAP listing quite a few reasons that message may appear (ie places to
check):
 <http://www.openldap.org/faq/data/cache/1432.html>

Note: I have no knowledge of its accuracy, it just seems like a useful
list of things for you to check up on.

>From the sounds of it the problem is usually a lot more harsh and fatal
than what yo are seeing. It is kind of odd that it only affects an
occasional request - as shown by your cachemgr report earlier *most*
requests go straight through nice and quickly.

This may be quite different, but: I saw similar weird "sometimes"
failures with an IMAP service last year. It turned out that fail2ban was
set with a slightly too-low threshold and was banning a particular
client on flakey Dial-Up internet connection when it was raining in
their neighbourhood. Their TCP connection losses caused a ban which we
were seeing only as failure to re-login some minutes later once the
clients mail program wanted to re-check new mail.

> 
> With more log (-d) i got a lot of this... (just a little). This is working
> negotiate_kerberos_pac.cc(376): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: INFO: Got PAC data of lengh 584
> negotiate_kerberos_pac.cc(180): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: INFO: Found 4 rids
> negotiate_kerberos_pac.cc(188): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: Info: Got rid: 1168
> negotiate_kerberos_pac.cc(188): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: Info: Got rid: 512
> negotiate_kerberos_pac.cc(188): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: Info: Got rid: 513
> negotiate_kerberos_pac.cc(188): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: Info: Got rid: 1132
> negotiate_kerberos_pac.cc(256): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: INFO: Got DomainLogonId
> S-1-5-21-3939648023-1419124151
> -3306617744
> negotiate_kerberos_pac.cc(278): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: INFO: Found 1 ExtraSIDs
> negotiate_kerberos_pac.cc(327): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: INFO: Got ExtraSid S-1-18-1
> negotiate_kerberos_pac.cc(456): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: INFO: Read 540 of 584 bytes 
> negotiate_kerberos_auth.cc(778): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: DEBUG: Groups
> group=AQUAAAAAAAUVAAAAF0LS6rcdllSQ+xbFk
> AQAAA== group=AQUAAAAAAAUVAAAAF0LS6rcdllSQ+xbFAAIAAA==
> group=AQUAAAAAAAUVAAAAF0LS6rcdllSQ+xbFAQIAAA==
> group=AQUAAAAAAAUVAAAAF0LS6rcdllSQ+xbFbA
> QAAA== group=AQEAAAAAABIBAAAA
> negotiate_kerberos_auth.cc(783): pid=3973 :2018/02/27 12:08:33|
> negotiate_kerberos_auth: DEBUG: AF ...
> user at MYDOMAIN.LAN
> negotiate_kerberos_auth.cc(610): pid=3973 :2018/02/27 12:08:37|
> negotiate_kerberos_auth: DEBUG: Got 'YR...
> from squid (length: 2447).

This is mostly the data flow between Squid and the helper. That one
appears to be successful (found the groups=* lists).

There may be something about user credentials that breaks the LDAP
lookup, but AFAICT the failure is happening at the connect/bind stage
before any of the user info is sent to LDAP (I may be wrong there, my
knowledge of LDAP is low).

> 
> But, in some moments i get again the :
> kerberos_ldap_group: ERROR: Error while binding to ldap server with
> SASL/GSSAPI: Can't contact LDAP server
> 
> This is probably a Windows server, i repeat, but i ask for if someone know
> what can i do. (and maybe ensure that is not a squid problem)
> 
> (Again sorry with continue with this).

Don't be sorry, help is part of what this list is for.
I just hope that someone with better LDAP know-how can assist you better
or the above clues give you an idea.

Amos