Re: [squid-users] Kerberos negotiate slow avg service time

[Amos Jeffries]

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

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=AQUAAAUVF0LS6rcdllSQ+xbFk
> AQAAA== group=AQUAAAUVF0LS6rcdllSQ+xbFAAIAAA==
> group=AQUAAAUVF0LS6rcdllSQ+xbFAQIAAA==
> group=AQUAAAUVF0LS6rcdllSQ+xbFbA
> QAAA== group=AQEAABIB
> negotiate_kerberos_auth.cc(783): pid=3973 

Re: [squid-users] Kerberos negotiate slow avg service time

[erdosain9]

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::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). 

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=AQUAAAUVF0LS6rcdllSQ+xbFk
AQAAA== group=AQUAAAUVF0LS6rcdllSQ+xbFAAIAAA==
group=AQUAAAUVF0LS6rcdllSQ+xbFAQIAAA==
group=AQUAAAUVF0LS6rcdllSQ+xbFbA
QAAA== group=AQEAABIB
negotiate_kerberos_auth.cc(783): pid=3973 :2018/02/27 12:08:33|
negotiate_kerberos_auth: DEBUG: AF
oYG2MIGzoAMKAQChCwYJKoZIgvcSAQICooGeBIGbYIG
YBgkqhkiG9xIBAgICAG+BiDCBhaADAgEFoQMCAQ+ieTB3oAMCARKicARub5MOjpO177M/gXJcAdluTnj+29wfwmcbZJVIFDyiXBKLScmwPhaPd2sH4IvcEiBhgddiTbURTRfM7OsWlql7+
uS2I4WWSke5bcRYRIaprvgl3wtCoX9PjSQEmYL0H8LIBL0sQh2fbYftAXyxMGs=
u...@mydomain.lan
negotiate_kerberos_auth.cc(610): pid=3973 :2018/02/27 12:08:37|
negotiate_kerberos_auth: DEBUG: Got 'YR
YIIHJQYGKwYBBQUCoIIHGTCCBxWgMDAuBgkqhk
iC9xIBAgIGCSqGSIb3EgECAgYKKwYBBAGCNwICHgYKKwYBBAGCNwICCqKCBt8EggbbYIIG1wYJKoZIhvcSAQICAQBuggbGMIIGwqADAgEFoQMCAQ6iBwMFACCjggUDYYIE/zCCBPug
AwIBBaEMGwpFTVBEREguTEFOoiMwIaADAgECoRowGBsESFRUUBsQcHJveHkuZW1wZGRoLmxhbqOCBL8wggS7oAMCARKhAwIBA6KCBK0EggSpV5Ofs3WVdVBcsFv+Hm0rIqwv8Lnra2qZOa
8cldCaPT4j6lGbmhe4JphrdI8H+dJbZI42SC1WLj6ettPI1OB5JPc340A6q3X7f9Zjp1rplc/6/n2mNooCah+Epq83CeI2w1bjX24sIwv5Vj5fNv9l5tzRI2vm5hry828+jNNGEamR0Vi5
1wy1HpFRVm39xExs9HiIdVRuVLC2sgXPf3PLLlmE5pKPATPW074v045VnrYXFERgyFN45Le4oBqavwtQ4yxdnVt/3wHzx9B2jYckYp0EMbS4yHMH8trwNJwYWji7zTINkD1s81EMCl0t0R
bQBwt8rLbcYLurOpj95nicRZbfSAkNozbVo1i4sYApjqxZG1xPK1JdNYc927kCayiTSa6emuD2LbXaY47phntoGg77k8JvaSeqL/yNMhPS8/k5PuE1qSaQjSvatAiqUF8fWQRu9O8f4uhQ
LyseKPkBiO6Ll/NgQFXhAQOwxyvunbLZhVz568UsP1EMw8IRU8m6CRXoyHB9xFQVS+QI3PBYXzD3eFtYfofbXJjYm97VZrB+CmmU5K72Azm/bQzwybSbDhqLo9FyKAR2K9lFp0q3/Gt/Gf

Re: [squid-users] Kerberos negotiate slow avg service time

[Amos Jeffries]

On 24/02/18 06:29, erdosain9 wrote:
> Hi to all.
> I dont know why i have this bad values. My network is woking fine. How i can
> do to fix this. I think is a high value.
> 
> HTTP/1.1 200 OK
> Server: squid/3.5.27
> Mime-Version: 1.0
> Date: Fri, 23 Feb 2018 17:16:25 GMT
> Content-Type: text/plain;charset=utf-8
> Expires: Fri, 23 Feb 2018 17:16:25 GMT
> Last-Modified: Fri, 23 Feb 2018 17:16:25 GMT
> X-Cache: MISS from proxy.mydomain.lan
> X-Cache-Lookup: MISS from proxy.mydomain.lan:3128
> Via: 1.1 proxy.mydomain.lan (squid/3.5.27)
> Connection: close
> 
> Negotiate Authenticator Statistics:
> program: /lib64/squid/negotiate_kerberos_auth
> number active: 50 of 50 (0 shutting down)
> requests sent: 4106
> replies received: 4105
> queue length: 0
> avg service time: 82 msec

The above "avg service time" is not bad for a system as complicated as
Kerberos. Note that this is significantly less than the outstanding
requests listed below in the report. That is a sign that a very large
number of the lookups are performed very, very fast.

In other words; what you see in the report is _only_ the odd ones that
do go slow enough to show up there. With maybe, at most, a few of the
faster ones that happened by chance to be partially done at the instant
the report was generated.


Be aware that it is normal for a helper which has not been used much to
require time to refresh its internal state in order to process a
request. Avoiding that problem is why you see the clear pattern of
#Requests going to one helper, with a second getting most of the
remainder and so on. Squid intentionally biases lookups towards the most
recently used/updated helper. Also, the longer delay times visible being
for the later helpers down the list is another side effect of that problem.


As Yuri cryptically asked, did this come to your attention due to
customer complaints? or just while observing the reports?
 if it is not causing observable issues to the clients I would not worry.

If you want to tune the helpers better than default, you can maybe
further reduce that state refresh by configuring the helper with
explicit details about what backed server to be contacting. A lot of the
delays are caused by sequences of DNS lookups and parsing + processing
the machine KeyTab files. The debug (-d) option of the helper itself can
assist you with identifying which of its internal processes is going
slowest. Just try not to drown in the flood of data from those very,
very fast ones.


> 
>ID #FD PID  # Requests   # Replies  Flags Time 
>  Offset
> Request
>  2118   5725911831182 B R   0.293 
>   0 (none)
>  2222   57260 652 652   0.164 
>   0 (none)
...

> 
> 
> ###Kerberos Auth with ActiveDirectory###
> auth_param negotiate program /lib64/squid/negotiate_kerberos_auth -s
> HTTP/proxy.empddh@empddh.lan
> auth_param negotiate children 50 startup=0 idle=1
> auth_param basic credentialsttl 2 hours
> auth_param negotiate keep_alive on
> 

___
squid-users mailing list
squid-users@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-users

Re: [squid-users] Kerberos negotiate slow avg service time

[Yuri]

Users complains?


23.02.2018 23:29, erdosain9 пишет:
> Hi to all.
> I dont know why i have this bad values. My network is woking fine. How i can
> do to fix this. I think is a high value.
>
> HTTP/1.1 200 OK
> Server: squid/3.5.27
> Mime-Version: 1.0
> Date: Fri, 23 Feb 2018 17:16:25 GMT
> Content-Type: text/plain;charset=utf-8
> Expires: Fri, 23 Feb 2018 17:16:25 GMT
> Last-Modified: Fri, 23 Feb 2018 17:16:25 GMT
> X-Cache: MISS from proxy.mydomain.lan
> X-Cache-Lookup: MISS from proxy.mydomain.lan:3128
> Via: 1.1 proxy.mydomain.lan (squid/3.5.27)
> Connection: close
>
> Negotiate Authenticator Statistics:
> program: /lib64/squid/negotiate_kerberos_auth
> number active: 50 of 50 (0 shutting down)
> requests sent: 4106
> replies received: 4105
> queue length: 0
> avg service time: 82 msec
>
>ID #FD PID  # Requests   # Replies  Flags Time 
>  Offset
> Request
>  2118   5725911831182 B R   0.293 
>   0 (none)
>  2222   57260 652 652   0.164 
>   0 (none)
>  2342   57261 440 440   0.163 
>   0 (none)
>  2446   57262 307 307   0.962 
>   0 (none)
>  2548   57263 223 223   0.642 
>   0 (none)
>  2650   57264 180 180   0.642 
>   0 (none)
>  2755   57265 138 138   1.048 
>   0 (none)
>  2859   57266 115 115   1.158 
>   0 (none)
>  2965   57267  90  90   1.193 
>   0 (none)
>  3056   57268  77  77   1.193 
>   0 (none)
>  3174   57269  69  69   1.193 
>   0 (none)
>  3276   57270  64  64   1.039 
>   0 (none)
>  3378   57271  56  56   1.015 
>   0 (none)
>  3480   57272  54  54   0.993 
>   0 (none)
>  3582   57273  46  46   0.956 
>   0 (none)
>  3684   57274  39  39   0.763 
>   0 (none)
>  3779   57275  37  37   0.763 
>   0 (none)
>  3883   57276  31  31   0.690 
>   0 (none)
>  3994   57277  28  28   0.635 
>   0 (none)
>  4096   57278  26  26   0.624 
>   0 (none)
>  4198   57279  25  25   0.577 
>   0 (none)
>  42   100   57280  23  23   0.504 
>   0 (none)
>  43   102   57281  20  20   1.262 
>   0 (none)
>  4499   57282  20  20   1.259 
>   0 (none)
>  45   122   57283  17  17   1.252 
>   0 (none)
>  46   124   57284  16  16   0.836 
>   0 (none)
>  47   126   57285  14  14   0.796 
>   0 (none)
>  48   128   57286  14  14   0.543 
>   0 (none)
>  49   119   57287  13  13   0.520 
>   0 (none)
>  50   125   57288  11  11   0.942 
>   0 (none)
>  52   222   57292   8   8   0.900 
>   0 (none)
>  53   224   57293   7   7   0.921 
>   0 (none)
>  54   227   57294   6   6   0.740 
>   0 (none)
>  55   230   57295   5   5   1.912 
>   0 (none)
>  56   231   57296   4   4   1.979 
>   0 (none)
>  57   233   57297   5   5   1.857 
>   0 (none)
>  58   236   57298   5   5   1.665 
>   0 (none)
>  59   237   57299   5   5   1.652 
>   0 (none)
>  60   239   57300   4   4   1.659 
>   0 (none)
>  61   241   57301   5   5   1.614 
>   0 (none)
>  62   243   57304   5   5   1.499 
>   0 (none)
>  63   245   57305   5   5   

[squid-users] Kerberos negotiate slow avg service time

[erdosain9]

Hi to all.
I dont know why i have this bad values. My network is woking fine. How i can
do to fix this. I think is a high value.

HTTP/1.1 200 OK
Server: squid/3.5.27
Mime-Version: 1.0
Date: Fri, 23 Feb 2018 17:16:25 GMT
Content-Type: text/plain;charset=utf-8
Expires: Fri, 23 Feb 2018 17:16:25 GMT
Last-Modified: Fri, 23 Feb 2018 17:16:25 GMT
X-Cache: MISS from proxy.mydomain.lan
X-Cache-Lookup: MISS from proxy.mydomain.lan:3128
Via: 1.1 proxy.mydomain.lan (squid/3.5.27)
Connection: close

Negotiate Authenticator Statistics:
program: /lib64/squid/negotiate_kerberos_auth
number active: 50 of 50 (0 shutting down)
requests sent: 4106
replies received: 4105
queue length: 0
avg service time: 82 msec

   ID #  FD PID  # Requests   # Replies  Flags Time  Offset
Request
 21  18   5725911831182 B R   0.293   0 
(none)
 22  22   57260 652 652   0.164   0 
(none)
 23  42   57261 440 440   0.163   0 
(none)
 24  46   57262 307 307   0.962   0 
(none)
 25  48   57263 223 223   0.642   0 
(none)
 26  50   57264 180 180   0.642   0 
(none)
 27  55   57265 138 138   1.048   0 
(none)
 28  59   57266 115 115   1.158   0 
(none)
 29  65   57267  90  90   1.193   0 
(none)
 30  56   57268  77  77   1.193   0 
(none)
 31  74   57269  69  69   1.193   0 
(none)
 32  76   57270  64  64   1.039   0 
(none)
 33  78   57271  56  56   1.015   0 
(none)
 34  80   57272  54  54   0.993   0 
(none)
 35  82   57273  46  46   0.956   0 
(none)
 36  84   57274  39  39   0.763   0 
(none)
 37  79   57275  37  37   0.763   0 
(none)
 38  83   57276  31  31   0.690   0 
(none)
 39  94   57277  28  28   0.635   0 
(none)
 40  96   57278  26  26   0.624   0 
(none)
 41  98   57279  25  25   0.577   0 
(none)
 42 100   57280  23  23   0.504   0 
(none)
 43 102   57281  20  20   1.262   0 
(none)
 44  99   57282  20  20   1.259   0 
(none)
 45 122   57283  17  17   1.252   0 
(none)
 46 124   57284  16  16   0.836   0 
(none)
 47 126   57285  14  14   0.796   0 
(none)
 48 128   57286  14  14   0.543   0 
(none)
 49 119   57287  13  13   0.520   0 
(none)
 50 125   57288  11  11   0.942   0 
(none)
 52 222   57292   8   8   0.900   0 
(none)
 53 224   57293   7   7   0.921   0 
(none)
 54 227   57294   6   6   0.740   0 
(none)
 55 230   57295   5   5   1.912   0 
(none)
 56 231   57296   4   4   1.979   0 
(none)
 57 233   57297   5   5   1.857   0 
(none)
 58 236   57298   5   5   1.665   0 
(none)
 59 237   57299   5   5   1.652   0 
(none)
 60 239   57300   4   4   1.659   0 
(none)
 61 241   57301   5   5   1.614   0 
(none)
 62 243   57304   5   5   1.499   0 
(none)
 63 245   57305   5   5   1.308   0 
(none)
 71 450   57317   3   3   0.855   0 
(none)
 72 452   57318   2   2   0.515   0 
(none)
 73 453   57319   1   1   3.052   0 
(none)
 74 455   57320   2   2   0.703   0 
(none)
 75 457   57321   2   2   0.572   0 
(none)
 76 458   57322   1   1