Re: [squid-users] negotiate_kerberos_auth helpers stay busy
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 %MEMVSZ 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 squid27950 0.8 67.8 13404452 8262560 ?SAug01 6:34 \_ (squid-1) -f /etc/squid/squid-C.conf squid27951 0.0 0.0 76828 1864 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27952 0.0 0.0 76828 1516 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27953 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27954 0.0 0.0 72484 992 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27955 0.0 0.0 72484 992 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27956 0.0 0.0 76704 1788 ?SAug01 0:01 \_ (ext_kerberos_ldap_group_acl) squid27957 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27958 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27959 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27960 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27961 0.0 0.0 76704 1800 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27962 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27963 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27964 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27965 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27966 0.0 0.0 76660 1512 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27967 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27968 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27969 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27970 0.0 0.0 72484 992 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27971 0.0 0.0 72484 992 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27972 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27973 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27974 0.0 0.0 72484 992 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27975 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27976 0.0 0.0 76660 1668 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27977 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27978 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27979 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27980 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27981 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27982 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27983 0.0 0.0 72484 988 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27984 0.0 0.0 72484 992 ?SAug01 0:00 \_ (ext_kerberos_ldap_group_acl) squid27985
Re: Re: [squid-users] negotiate_kerberos_auth helpers stay busy
Hi, I am running squid 3.2.1 on CentOS 6.3 with kerberos authentication using negotiate_kerberos_auth. Generally this is working fine, but after some time more and more helper instances stay busy and cannot finish the given request. Therefore squid starts new helper processes to have enough working helpers for kerberos authentication. This release of Squid is quite old now. Are you able to upgrade your proxy to the current stable release and see if the problem disappears? (today that would be 3.3.8) You can find recent versions packages for CentOS at http://wiki.squid-cache.org/KnowledgeBase/CentOS. I would like to update squid to version 3.3.8 but there is still the problem that URLs that contain an ip address are not forwarded to cache peers (see Bug 3848). Therefore it is not usable for me. But I tested squid 3.3.8 on my test system and there was exactly the same problem with kerberos authentication. This is going on until squid has no more memory for the helpers: 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? Negotiate Authenticator Statistics: program: /usr/lib64/squid/negotiate_kerberos_auth number active: 39 of 500 (0 shutting down) requests sent: 11141 replies received: 11133 queue length: 0 avg service time: 4 msec # FD PID # Requests Flags Time Offset Request 1 19 31373 753 B R 3887.019 0 1 37 31390 755 B R 3637.061 0 1 39 313912539 B R 2053.518 0 1 41 31392 78 B R 3859.365 0 1 43 31393 807 B R 2008.036 0 1 57 31396 415 B R 2003.899 0 1 63 31397 363 B R 1975.126 0 1 95 31401 329 B R 1944.980 0 1 29 314911891 0.009 0 (none) 1 77 31492 813 0.011 0 (none) 1 88 31493 578 0.009 0 (none) The first eight helper processes are busy and will never return to normal state until squid is restarted. Gradually more and more helpers stay in busy state. strace shows me that this helpers are blocked during a read-command: read(0, r, 1) = 1 read(0, r, 1) = 1 read(0, 7, 1) = 1 read(0, +, 1) = 1 read(0, a, 1) = 1 read(0, G, 1) = 1 read(0, unfinished ... After this the process is never continued. That does not look blocked to me. The value arriving is changing, just eee ssslloowwwlllyyy, one byte per I/O cycle to be exact. Since kerberos credentials can be up to 32 KB large its easy to see why they are stuck in BUSY state for such long times. But Microsoft says that there can be kerberos credentials up to 64 KB (http://support.microsoft.com/kb/327825/en-us). And I think that's the problem. Our Active Directory has actually kerberos credentials up to 40 KB and I found out that exactly these credentials put the kerberos helper in the busy state. strace shows me that the helper process reads credential bytes from squid up to 32 KB then it waits at the socket for the rest and stays busy, but squid doesn't transmit any bytes more than 32 KB. Therefore the helper never finishes the authentication and is no longer usable. Users with kerberos credentials greater than 32 k cannot use squid and cause blocked helper processes. Is there a solution for such long kerberos credentials? I cannot find any error messages in cache.log even if I switch on debugging at the helper. At this rate of I/O in the helper it is unlikely that they will be able to send a message to cache.log in any reasonable time. Thank you for help! Klaus
[squid-users] negotiate_kerberos_auth helpers stay busy
Hi, I am running squid 3.2.1 on CentOS 6.3 with kerberos authentication using negotiate_kerberos_auth. Generally this is working fine, but after some time more and more helper instances stay busy and cannot finish the given request. Therefore squid starts new helper processes to have enough working helpers for kerberos authentication. This is going on until squid has no more memory for the helpers: 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 2013/07/30 08:48:04 kid1| WARNING: Cannot run '/usr/lib64/squid/negotiate_kerberos_auth' process. The problem can only be solved by restarting squid. squidclient mgr:negotiateauthenticator shows the problem (I put away the large kerberos requests waiting to be finished): Negotiate Authenticator Statistics: program: /usr/lib64/squid/negotiate_kerberos_auth number active: 39 of 500 (0 shutting down) requests sent: 11141 replies received: 11133 queue length: 0 avg service time: 4 msec # FD PID # Requests Flags Time Offset Request 1 19 31373 753 B R 3887.019 0 1 37 31390 755 B R 3637.061 0 1 39 313912539 B R 2053.518 0 1 41 31392 78 B R 3859.365 0 1 43 31393 807 B R 2008.036 0 1 57 31396 415 B R 2003.899 0 1 63 31397 363 B R 1975.126 0 1 95 31401 329 B R 1944.980 0 1 29 314911891 0.009 0 (none) 1 77 31492 813 0.011 0 (none) 1 88 31493 578 0.009 0 (none) 1 99 31494 430 0.009 0 (none) 1 111 31512 320 0.010 0 (none) 1 115 31513 200 0.018 0 (none) 1 117 31514 158 0.014 0 (none) 1 119 31515 122 0.013 0 (none) 1 121 31516 99 0.011 0 (none) 1 123 31517 82 0.014 0 (none) 1 125 31518 66 0.012 0 (none) 1 118 31519 58 0.010 0 (none) 1 113 32414 44 0.013 0 (none) 1 116 32415 36 0.015 0 (none) 1 124 367 29 0.014 0 (none) 1 128 368 28 0.015 0 (none) 1 137 375 24 0.012 0 (none) 1 138 376 21 0.015 0 (none) 1 140 377 16 0.040 0 (none) 1 142 378 15 0.036 0 (none) 1 144 379 14 0.033 0 (none) 1 1393490 11 0.037 0 (none) 1 1433491 10 0.036 0 (none) 1 1463495 8 0.037 0 (none) 1 1483496 7 0.046 0 (none) 1 1503497 6 0.047 0 (none) 1 1453498 5 0.047 0 (none) 1 1493499 4 0.041 0 (none) 1 1523500 3 0.104 0 (none) 1 1543501 2 0.105 0 (none) 1 1563502 2 0.089 0 (none) Flags key: B = BUSY C = CLOSING R = RESERVED S = SHUTDOWN PENDING P = PLACEHOLDER The first eight helper processes are busy and will never return to normal state until squid is restarted. Gradually more and more helpers stay in busy state. strace shows me that this helpers are blocked during a read-command: read(0, r, 1) = 1 read(0, r, 1) = 1 read(0, 7, 1) = 1 read(0, +, 1) = 1 read(0, a, 1) = 1 read(0, G, 1) = 1 read(0, unfinished ... After this the process is never continued. I cannot find any error messages in cache.log even if I switch on debugging at the helper. Thank you for help! Klaus
Re: [squid-users] negotiate_kerberos_auth helpers stay busy
On 31/07/2013 9:18 a.m., Klaus Walter wrote: Hi, I am running squid 3.2.1 on CentOS 6.3 with kerberos authentication using negotiate_kerberos_auth. Generally this is working fine, but after some time more and more helper instances stay busy and cannot finish the given request. Therefore squid starts new helper processes to have enough working helpers for kerberos authentication. This release of Squid is quite old now. Are you able to upgrade your proxy to the current stable release and see if the problem disappears? (today that would be 3.3.8) You can find recent versions packages for CentOS at http://wiki.squid-cache.org/KnowledgeBase/CentOS. This is going on until squid has no more memory for the helpers: 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? Negotiate Authenticator Statistics: program: /usr/lib64/squid/negotiate_kerberos_auth number active: 39 of 500 (0 shutting down) requests sent: 11141 replies received: 11133 queue length: 0 avg service time: 4 msec # FD PID # Requests Flags Time Offset Request 1 19 31373 753 B R 3887.019 0 1 37 31390 755 B R 3637.061 0 1 39 313912539 B R 2053.518 0 1 41 31392 78 B R 3859.365 0 1 43 31393 807 B R 2008.036 0 1 57 31396 415 B R 2003.899 0 1 63 31397 363 B R 1975.126 0 1 95 31401 329 B R 1944.980 0 1 29 314911891 0.009 0 (none) 1 77 31492 813 0.011 0 (none) 1 88 31493 578 0.009 0 (none) The first eight helper processes are busy and will never return to normal state until squid is restarted. Gradually more and more helpers stay in busy state. strace shows me that this helpers are blocked during a read-command: read(0, r, 1) = 1 read(0, r, 1) = 1 read(0, 7, 1) = 1 read(0, +, 1) = 1 read(0, a, 1) = 1 read(0, G, 1) = 1 read(0, unfinished ... After this the process is never continued. That does not look blocked to me. The value arriving is changing, just eee ssslloowwwlllyyy, one byte per I/O cycle to be exact. Since kerberos credentials can be up to 32 KB large its easy to see why they are stuck in BUSY state for such long times. I cannot find any error messages in cache.log even if I switch on debugging at the helper. At this rate of I/O in the helper it is unlikely that they will be able to send a message to cache.log in any reasonable time. Thank you for help! Klaus
Fwd: [squid-users] negotiate_kerberos_auth helpers stay busy
On Wed, Jul 31, 2013 at 6:59 AM, Amos Jeffries squ...@treenet.co.nz wrote: On 31/07/2013 9:18 a.m., Klaus Walter wrote: strace shows me that this helpers are blocked during a read-command: read(0, r, 1) = 1 read(0, r, 1) = 1 read(0, 7, 1) = 1 read(0, +, 1) = 1 read(0, a, 1) = 1 read(0, G, 1) = 1 read(0, unfinished ... After this the process is never continued. That does not look blocked to me. The value arriving is changing, just eee ssslloowwwlllyyy, one byte per I/O cycle to be exact. Since kerberos credentials can be up to 32 KB large its easy to see why they are stuck in BUSY state for such long times. I see the helper is reading one byte at a time. The code for the kerberos explicitly disables buffering: setbuf(stdout, NULL); setbuf(stdin, NULL); As a test, I removed setbuf(stdin, NULL), and it works well: the helper no longer reads one byte at a time, but the whole thing at once. I tried to take it further and enable buffering for stdout as well, but it doesn't work: the helpers don't write anything until the buffer is full, so it just hangs. I think glibc only flushes stdout on newline when stdout is a terminal. So I added explicit calls to fflush() after each fprintf(stdout, ...), and now it works like a charm. I haven't measured the performance improvement with this, and I'm sure it doesn't solve Klaus' issue, but I am very interested in improving performance in every possible way, even if its a small improvement. If anybody is interested, please see the attached patch against Squid 3.3.8. Best regards, Alan I'm resending this message because it was rejected due to the attachment. If you are interested in the patch, please run: echo H4sICJB6+FEAA25lZ290aWF0ZV9rZXJiZXJvc19hdXRoLWJ1ZmZlcmluZy5wYXRjaADtmG1z0zgQgD9ff8XSm7Z246R2nHcuMw3XAJ22KZT05m6g43Ft2TEksrHkQo/jv99KdlLHcQqlMBzDaTqNR7Z2tY92Vyu5gedBNYFqDOxtErhVs2bWOrUwDvy9CZlGJGZ7lPghD2xOLDvhk703JL4kcZjvn3fJD2qOk5d1DzEb1Wr1a07rl7pumFW9XTUNMIxew+wZ3VrXrNe7zY5pQkXv6vpGpVL5StMvqmv1TL1mtHRdb7Zb3Uzd/j5UjW5Xa0FF/LRhf38D5u0jvJsEUwLKjPmWw9+rD2/eueQy8RXFmdgx7KqwucX+gS3Wg+HZ2elZDx/Bs3GsKx5f0U0NjkN/HMyIomrw7Oz0ydngRAMvoQ4PQqrBZeLlpXtRHFDuKYy7YcI12Hz0tERkcXhlMdybJmySjc7LDTxQpqGv3vQUtJE41m6MORw9Pu3BOSMx0JCDAEsoDxzE7RaMWpY4b5mlOAUBum7WNQRfN03kPQfthJRxSCgLfEpcSIGySKzrOHxDKPRhdH58nBnBgr+JxSH3/phQn0/wKx0/2ajKjwhHIAt4YjjOoPAqoDdvUtnZYlcNeNAHJYw4CvUJxwfFjn1HA/x/hXTcIGa9yaaqqvDhxmz2LuDORI5b6ndsRmDH3elJBKYufc3U2wVfEyuD8JeGfoafnV5hcCATF2aEMdsna3wt7wTrHKxMVt6rbvUs0XD+2TrkGy4wD2hCct0fUxZGWzMMhGG0NMNcoYHr9FK/gH4fdl7pO3cFc0iv7GngQkzeJoTxe2BZlXQnKKXmLxnKeDwlVNirwm9Qv6el8HKLXazNOIU8891sfoBGU2cWCatR5fPnON+6DCjpGS1DRkmrXhIlyyP/OpMjYXsbll8cHS1E/mw0MyYLmu2UZtssp3njfH0wv5TXYh/+JuRWpH9lhjRKuMXFdlKbzveTS0zcrYblEid0iZVBqpjZXmZ20kTeLbroOlNi4pDgCpMrv44IbLkwGh+fgNQpKJXvnwqKUWFXUQr7o7o0ZWSUEKiUi5g3kdlDDyifzp7FIQ+dcKreCSGuQAjOlNg0iW5JZiS+ChxiCQJOENnTuRc26h0BrGGWARMjebrbp9v9ihuK9glXHGGJQmiY+BPcwGZhfP2ZSX/dipXJKxL7JLVbyBXoiZb5HKHS5zA2Uypa4YVwxpUSCGswydlMOTeK0T7nPLNfhzHKtnnCYBuevHhhvbB+Px2ND0fnQ2s0HB4MD+6EP60SswizRUGK8UrclRLxTvzH43mVKwl8Y+4+Y1ZM8EtGLIxyj8TK9iygC04abKOORcRlOaDRlIm10SwWc3PUiaicf26PRj1OdC1JaJBnmGatQl+afBd4ZYpttFoleEXbjSAtDm+fwgqJwWNxmMq7lwZigndKh+uW7mD46PxJD5Z0lO2Amd7Yc4y22bEIc+yISE5qUVX5qa1g2tqTG07j1oObRN3WJep254dOGqPBD5A0Oi2Jutv8P2msI3ufpNFtCLxNvfEtk8bmYNDvb36HrDFX/N9IG82GrnUQttwHBWyUugEzO6CicIX01iS1Nb3mETcoLy9wRh++7KZGzl4KFLcDJ4M/rcH5+On49Gg4so6Ho4uHSzc5xlL4CByeTzhLT0lpPZwefKpgYIfQpOYjLzVRbkLNZllmJO8DruhqeTVcFktH2R1lHq1MfRhjLImiME5Jf/IyD/Xg36+EumjW3i48HfwxtDArD54dwu7exr8zzzqnWBYAAA== | perl -MCompress::Zlib -MMIME::Base64 -e 'print Compress::Zlib::memGunzip(decode_base64())' /tmp/negotiate_kerberos_auth-buffering.patch
