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

Hi Klaus,

   Thank you for the valgrind output. Could you compile and link the helper
with -g to get the source code line.

Thank you
Markus

"Klaus Walter" <klaus.walter_at_spb.de> wrote in message
news:20130805115312.15524n2zj4ecq680_at_webmail.mnet-online.de...
> 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 |
> algrind --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 - 18:50:09 MDT