Re: [squid-users] Re: negotiate_kerberos_auth helpers stay busy

Hi Markus,

thank you very much for your help.

I changed MAX_AUTHTOKEN_LEN to 64 KB and recompiled squid.
After that there are no longer any hanging negotiate_kerberos_auth
helper processes.
This problem is fixed now.

For the memory problem I tried to debug with valgrind and I hope
I did it in the right way:

./negotiate_kerberos_auth_test proxyk1.spb.de testuser | valgrind
--log-file=/tmp/negotiate_kerberos_auth.val --leak-check=full
--show-reachable=yes -v ./negotiate_kerberos_auth -r -s GSS_C_NO_NAME

Here the last part of the output:

==26714== HEAP SUMMARY:
==26714== in use at exit: 14 bytes in 1 blocks
==26714== total heap usage: 59 allocs, 58 frees, 6,863 bytes allocated
==26714==
==26714== Searching for pointers to 1 not-freed blocks
==26714== Checked 318,728 bytes
==26714==
==26714== 14 bytes in 1 blocks are definitely lost in loss record 1 of 1
==26714== at 0x4A069EE: malloc (vg_replace_malloc.c:270)
==26714== by 0x403384: xmalloc (in
/usr/lib64/squid/negotiate_kerberos_auth)
==26714== by 0x40359B: xstrdup (in
/usr/lib64/squid/negotiate_kerberos_auth)
==26714== by 0x401ADE: main (in /usr/lib64/squid/negotiate_kerberos_auth)
==26714==
==26714== LEAK SUMMARY:
==26714== definitely lost: 14 bytes in 1 blocks
==26714== indirectly lost: 0 bytes in 0 blocks
==26714== possibly lost: 0 bytes in 0 blocks
==26714== still reachable: 0 bytes in 0 blocks
==26714== suppressed: 0 bytes in 0 blocks
==26714==
==26714== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 6 from 6)
--26714--
--26714-- used_suppression: 4 U1004-ARM-_dl_relocate_object
--26714-- used_suppression: 2 glibc-2.5.x-on-SUSE-10.2-(PPC)-2a
==26714==
==26714== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 6 from 6)

It shows a lost of bytes.

Please tell me what I should do for further informations.

Klaus

>
> Hi Klaus
>
> If the token is to big then you need to update the source here:
>
> src/auth/UserRequest.h:#define MAX_AUTHTOKEN_LEN 32768
>
> I am curious about the memory leak as I run it through valgrind ( I
> noticed some underlying Kerberos library leaks, but no leaks in the helper
>
> itself). Can you run valgrind against the helper if I give you the
> instructions ?
>
> Markus
>
> "Klaus Walter" <klaus.walter_at_spb.de> wrote in message
> news:20130802163540.207140vakmhtvcu8_at_webmail.mnet-online.de...
>> Hi Amos,
>>
>>
>>>> 2013/07/30 08:48:04 kid1| Starting new negotiateauthenticator
> helpers...
>>>> 2013/07/30 08:48:04 kid1| helperOpenServers: Starting 1/500
>>>> 'negotiate_kerberos_auth' processes
>>>> 2013/07/30 08:48:04 kid1| ipcCreate: fork: (12) Cannot allocate memory
>>>
>>> That is bad, it is unrelated to the helpers getting locked up though.
>>>
>>> How much RAM is the Squid worker process using at the time this
> appears?
>>> Starting helpers with fork() requires Squid to be allocated virtual
>>> memory 2x that being used at the time by the worker process.
>>>
>>> And how much memory is currently in use by each of those 8 BUSY
> helpers?
>>
>> So it seems that we have two different problems:
>>
>> The first problem is that our kerberos credentials from AD that are
>> greater
>> than 32 KB cause hanging helpers (see my last email).
>>
>> The other problem seems to be a memory leak in kerberos authentication.
>> I also tested the latest negotiate_kerberos_auth helper comming with
>> squid 3.3.8
>> together with my older squid, but the memory usage ist also increasing
>> until there is
>> no free memory available.
>>
>> Here you can see the memory usage when squid cannot allocate more
> memory:
>>
>> USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
>> root 8027 0.0 0.0 74932 292 ? Ss Aug01 0:00 squid
> -f
>> /etc/squid/squid-C.conf
>> squid 27950 0.8 67.8 13404452 8262560 ? S Aug01 6:34 \_
>> (squid-1) -f /etc/squid/squid-C.conf
>> squid 27951 0.0 0.0 76828 1864 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27952 0.0 0.0 76828 1516 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27953 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27954 0.0 0.0 72484 992 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27955 0.0 0.0 72484 992 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27956 0.0 0.0 76704 1788 ? S Aug01 0:01 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27957 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27958 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27959 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27960 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27961 0.0 0.0 76704 1800 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27962 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27963 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27964 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27965 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27966 0.0 0.0 76660 1512 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27967 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27968 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27969 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27970 0.0 0.0 72484 992 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27971 0.0 0.0 72484 992 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27972 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27973 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27974 0.0 0.0 72484 992 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27975 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27976 0.0 0.0 76660 1668 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27977 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27978 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27979 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27980 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27981 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27982 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27983 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27984 0.0 0.0 72484 992 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27985 0.0 0.0 72484 988 ? S Aug01 0:00 \_
>> (ext_kerberos_ldap_group_acl)
>> squid 27986 0.0 0.0 26484 448 ? S Aug01 0:00 \_
>> (unlinkd)
>> squid 27987 0.0 0.0 27000 744 ? S Aug01 0:02 \_
>> diskd 28620804 28620805 28620806
>> squid 27988 0.0 0.0 27000 748 ? S Aug01 0:02 \_
>> diskd 28620808 28620809 28620810
>> squid 27989 0.0 0.0 27000 764 ? S Aug01 0:02 \_
>> diskd 28620812 28620813 28620814
>> squid 27990 0.0 0.0 27000 756 ? S Aug01 0:02 \_
>> diskd 28620816 28620817 28620818
>> squid 28010 0.4 0.0 44916 1116 ? S Aug01 3:42 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 28058 0.1 0.0 44992 1116 ? S Aug01 1:11 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 29643 0.0 0.0 44976 1132 ? S Aug01 0:36 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 29644 0.0 0.0 44936 1120 ? S Aug01 0:26 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 29645 0.0 0.0 44944 1124 ? S Aug01 0:17 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 29646 0.0 0.0 44944 1116 ? S Aug01 0:12 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 21264 0.0 0.0 45192 1356 ? S 02:30 0:26 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 16792 0.1 0.0 45164 1120 ? S 06:11 0:20 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 20254 0.0 0.0 45056 1120 ? S 06:42 0:09 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 20291 0.0 0.0 45068 1120 ? S 06:43 0:07 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 20486 0.1 0.0 45092 1188 ? S 06:44 0:33 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 20487 0.1 0.0 45080 1320 ? S 06:44 0:20 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23102 0.3 0.0 44896 1124 ? S 07:07 0:54 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23103 0.1 0.0 44976 1148 ? S 07:07 0:23 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23104 0.0 0.0 44972 1124 ? S 07:07 0:14 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23105 0.0 0.0 44980 1180 ? S 07:07 0:09 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23106 0.0 0.0 44972 1208 ? S 07:07 0:09 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23107 0.0 0.0 44980 1164 ? S 07:07 0:12 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23108 0.0 0.0 45084 1156 ? S 07:07 0:13 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23109 0.0 0.0 45080 1128 ? S 07:07 0:08 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23433 0.0 0.0 45068 1240 ? S 07:10 0:09 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23434 0.0 0.0 45168 1276 ? S 07:10 0:12 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23435 0.3 0.0 45200 1316 ? S 07:10 0:59 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23436 0.2 0.0 45064 1152 ? S 07:10 0:33 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23437 0.1 0.0 45072 1160 ? S 07:10 0:17 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 23438 0.1 0.0 45172 1116 ? S 07:10 0:23 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 25002 0.0 0.0 45168 1120 ? S 07:24 0:14 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 25824 0.0 0.0 141528 6152 ? S 07:31 0:00 \_
>> /usr/bin/perl -w /usr/local/squid/bin/authenticator.pl
>> squid 26539 0.0 0.0 45248 1144 ? S 07:37 0:09 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 26540 0.1 0.0 45248 1128 ? S 07:37 0:17 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 26544 0.0 0.0 45244 1152 ? S 07:37 0:12 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 26545 0.0 0.0 45240 1144 ? S 07:37 0:09 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 29535 0.1 0.0 45240 1128 ? S 08:03 0:18 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 29536 0.1 0.0 45236 1416 ? S 08:03 0:24 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 29670 0.1 0.0 45304 1348 ? S 08:04 0:15 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 29771 0.5 0.0 45468 1524 ? S 08:05 1:08 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 29772 0.2 0.0 45496 1320 ? S 08:05 0:37 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 30614 0.2 0.0 45556 1764 ? S 08:13 0:30 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 30615 0.4 0.0 45808 1748 ? S 08:13 0:57 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 30616 0.1 0.0 45556 1976 ? S 08:13 0:15 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 1114 0.4 0.0 45588 1940 ? S 08:36 0:47 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 1115 0.2 0.0 45600 2140 ? S 08:36 0:28 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 1116 0.1 0.0 45616 2396 ? S 08:37 0:19 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 1120 0.1 0.0 45644 2396 ? S 08:37 0:14 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 1121 0.0 0.0 45640 2328 ? S 08:37 0:10 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 1122 0.0 0.0 45632 2292 ? S 08:37 0:08 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 1200 0.2 0.0 45192 2008 ? S 08:37 0:31 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 1201 0.2 0.0 45196 2000 ? S 08:37 0:28 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 1202 0.0 0.0 45552 2340 ? S 08:37 0:04 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3674 0.1 0.0 45188 2060 ? S 08:56 0:11 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3675 0.0 0.0 45220 2084 ? S 08:56 0:08 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3676 0.0 0.0 45184 2020 ? S 08:56 0:07 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3982 0.0 0.0 45264 2152 ? S 08:59 0:05 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3983 0.0 0.0 45264 2148 ? S 08:59 0:03 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3987 0.0 0.0 45268 2140 ? S 08:59 0:03 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3988 0.0 0.0 45260 2144 ? S 08:59 0:03 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3989 0.0 0.0 45264 2052 ? S 08:59 0:02 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3990 0.0 0.0 45260 2100 ? S 08:59 0:01 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3991 0.0 0.0 45260 2152 ? S 08:59 0:02 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3992 0.0 0.0 45268 2136 ? S 08:59 0:02 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3993 0.0 0.0 45264 2148 ? S 08:59 0:01 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3994 0.0 0.0 45264 2084 ? S 08:59 0:01 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3995 0.0 0.0 45276 2160 ? S 08:59 0:01 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3996 0.0 0.0 45280 2156 ? S 08:59 0:01 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3997 0.0 0.0 45276 2156 ? S 08:59 0:04 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3998 0.0 0.0 45276 2148 ? S 08:59 0:05 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 3999 0.0 0.0 45276 2168 ? S 08:59 0:01 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 4000 0.0 0.0 45320 2200 ? S 08:59 0:05 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 4001 0.0 0.0 45320 2196 ? S 08:59 0:02 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 4002 0.0 0.0 45328 2140 ? S 08:59 0:01 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 5727 0.3 0.0 45704 2520 ? S 09:13 0:28 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 5728 0.0 0.0 45700 2480 ? S 09:13 0:04 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>> squid 5729 0.0 0.0 45700 2436 ? S 09:13 0:02 \_
>> (negotiate_kerberos_auth) -r -s GSS_C_NO_NAME
>>
>> The server has 12 GB physical memory and 2 GB swap.
>>
>> Klaus
>>
>>
>>
>
>
>
>
Received on Mon Aug 05 2013 - 09:53:29 MDT