Re: Need 2.2.2 [was: FR 2.2.1 issue]
Found another thing. With 2.2.1 we were seeing a LOT of requests not being handled quickly. .. stuck in core messages. I say were because we've rolled back to 2.2.0 for now as we don't have time to debug this for a while. If someone else doesn't step in then can look into this in a couple of weeks (some serious developer debug left on slowing it?) alan
On 20.09.2013 19:22, Alan Buxey wrote:
Found another thing. With 2.2.1 we were seeing a LOT of requests not being handled quickly. .. stuck in core messages. I say were because we've rolled back to 2.2.0 for now as we don't have time to debug this for a while. If someone else doesn't step in then can look into this in a couple of weeks (some serious developer debug left on slowing it?)
Hmm... 2.2.1 is also behaving unclean at my site. I keep getting: Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:18 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:19 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:19 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:23 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:30 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:33 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:36 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:38 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:38 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. With a config that ran smoothly with 2.2.0 (+the fixes that I needed to get SSHA1 decoding to work in a satisfying way). I'm rolling back to that patched version now - the errors seem to create intermittent auth failures/timeouts. Stefan
alan
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473 PGP key updated to 4096 Bit RSA - I will encrypt all mails if the recipient's key is known to me http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xC0DE6A358A39DC66
Hi,
Hmm... 2.2.1 is also behaving unclean at my site. I keep getting:
right, too early in the morning. I may have jumped on that bandwaggon too quickly. We do see a significant increase in the below, but it seems "normal" in the sense that people are back to school and more inquisitive uninformed people trigger these... xlat fails because the User-Name doesn't exist in the DB (typo etc.) and there is no SSHA1 password to mangle. EAP session states go lost after about 9 round-trips of packets. 9 roundtrips is +- the time when asked for the username+password when outer TLS is set up, so there may be new users having no clue, and go searching for what to enter for more than the 120 (!) seconds I've set session matching timeout to. Stefan
Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:17 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:18 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:19 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:19 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:21 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:23 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:30 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:33 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:36 2013 : Error: rlm_expr: xlat failed. Mon Sep 23 08:01:38 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:38 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable. Mon Sep 23 08:01:41 2013 : Error: rlm_eap: No EAP session matching the State variable.
With a config that ran smoothly with 2.2.0 (+the fixes that I needed to get SSHA1 decoding to work in a satisfying way).
I'm rolling back to that patched version now - the errors seem to create intermittent auth failures/timeouts.
Stefan
alan
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473 PGP key updated to 4096 Bit RSA - I will encrypt all mails if the recipient's key is known to me http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xC0DE6A358A39DC66
Hi,
Found another thing. With 2.2.1 we were seeing a LOT of requests not being handled quickly. .. stuck in core messages. I say were because we've rolled back to 2.2.0 for now as we don't have time to debug this for a while. If someone else doesn't step in then can look into this in a couple of weeks (some serious developer debug left on slowing it?)
I finally also found those on a 2.2.1 which runs a simple, proxy-mostly config. I would rather have expected such things on our complex internal instance, but well. Looks like: Mon Sep 30 09:05:08 2013 : Error: WARNING: Unresponsive child for request 64232, in component <core> module <thread> Mon Sep 30 09:05:08 2013 : Error: WARNING: Unresponsive child for request 64233, in component <core> module <thread> Mon Sep 30 09:05:08 2013 : Error: WARNING: Unresponsive child for request 64234, in component <core> module <thread> Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64232 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64233 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64234 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64219 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64220 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64221 in component <core> module <thread>. Mon Sep 30 09:05:10 2013 : Info: WARNING: Child is hung for request 64082 in component <core> module <thread>. Mon Sep 30 09:05:10 2013 : Info: WARNING: Child is hung for request 64083 in component <core> module <thread>. Mon Sep 30 09:05:10 2013 : Info: WARNING: Child is hung for request 64084 in component <core> module <thread>. Mon Sep 30 09:05:10 2013 : Error: Discarding duplicate request from client eduroam-tld1-v4 port 42885 - ID: 119 due to unfinished request 64294 Mon Sep 30 09:05:10 2013 : Error: Discarding duplicate request from client eduroam-tld1-v4 port 42885 - ID: 120 due to unfinished request 64295 Mon Sep 30 09:05:10 2013 : Error: Discarding duplicate request from client eduroam-tld1-v4 port 42885 - ID: 121 due to unfinished request 64296 Mon Sep 30 09:05:10 2013 : Info: WARNING: Child is hung for request 64232 in component <core> module <thread>. Mon Sep 30 09:05:10 2013 : Info: WARNING: Child is hung for request 64233 in component <core> module <thread>. Mon Sep 30 09:05:10 2013 : Info: WARNING: Child is hung for request 64234 in component <core> module <thread>. Mon Sep 30 09:05:12 2013 : Info: WARNING: Child is hung for request 64232 in component <core> module <thread>. Mon Sep 30 09:05:12 2013 : Info: WARNING: Child is hung for request 64233 in component <core> module <thread>. Mon Sep 30 09:05:12 2013 : Info: WARNING: Child is hung for request 64234 in component <core> module <thread>. Mon Sep 30 09:05:12 2013 : Error: Discarding duplicate request from client eduroam-tld2-v4 port 58917 - ID: 104 due to unfinished request 64300 Mon Sep 30 09:05:12 2013 : Error: Discarding duplicate request from client eduroam-tld2-v4 port 58917 - ID: 105 due to unfinished request 64301 Mon Sep 30 09:05:12 2013 : Error: Discarding duplicate request from client eduroam-tld2-v4 port 58917 - ID: 106 due to unfinished request 64302 Mon Sep 30 09:05:13 2013 : Info: WARNING: Child is hung for request 64219 in component <core> module <thread>. Mon Sep 30 09:05:13 2013 : Info: WARNING: Child is hung for request 64220 in component <core> module <thread>. Mon Sep 30 09:05:13 2013 : Info: WARNING: Child is hung for request 64221 in component <core> module <thread>. Mon Sep 30 09:05:13 2013 : Info: WARNING: Child is hung for request 64122 in component <core> module <thread>. Mon Sep 30 09:05:13 2013 : Error: Discarding duplicate request from client eduroam-tld2-v4 port 58917 - ID: 107 due to unfinished request 64337 Mon Sep 30 09:05:14 2013 : Info: WARNING: Child is hung for request 63987 in component <core> module <thread>. Mon Sep 30 09:05:14 2013 : Info: WARNING: Child is hung for request 63988 in component <core> module <thread>. Mon Sep 30 09:05:14 2013 : Info: WARNING: Child is hung for request 63989 in component <core> module <thread>. Mon Sep 30 09:05:15 2013 : Error: Discarding duplicate request from client eduroam-tld1-v4 port 42885 - ID: 119 due to unfinished request 64294 Mon Sep 30 09:05:15 2013 : Error: Discarding duplicate request from client eduroam-tld1-v4 port 42885 - ID: 120 due to unfinished request 64295 Mon Sep 30 09:05:15 2013 : Error: Discarding duplicate request from client eduroam-tld1-v4 port 42885 - ID: 121 due to unfinished request 64296 Mon Sep 30 09:05:16 2013 : Info: WARNING: Child is hung for request 64232 in component <core> module <thread>. Mon Sep 30 09:05:16 2013 : Info: WARNING: Child is hung for request 64233 in component <core> module <thread>. Mon Sep 30 09:05:16 2013 : Info: WARNING: Child is hung for request 64234 in component <core> module <thread>. Mon Sep 30 09:05:16 2013 : Info: WARNING: Child is hung for request 64127 in component <core> module <thread>. Mon Sep 30 09:05:16 2013 : Info: WARNING: Child is hung for request 64128 in component <core> module <thread>. Mon Sep 30 09:05:16 2013 : Info: WARNING: Child is hung for request 64129 in component <core> module <thread>. Mon Sep 30 09:05:17 2013 : Info: WARNING: Child is hung for request 64002 in component <core> module <thread>. Mon Sep 30 09:05:17 2013 : Info: WARNING: Child is hung for request 64003 in component <core> module <thread>. Mon Sep 30 09:05:17 2013 : Info: WARNING: Child is hung for request 64004 in component <core> module <thread>. Just wondering... did the fixes for 2.2.2 include a fix for such "Child is hung" requests? I reverted the server to 2.2.0 and do not see these issues any more. Greetings, Stefan Winter -- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473 PGP key updated to 4096 Bit RSA - I will encrypt all mails if the recipient's key is known to me http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xC0DE6A358A39DC66
Hi,
config. I would rather have expected such things on our complex internal instance, but well. Looks like:
Mon Sep 30 09:05:08 2013 : Error: WARNING: Unresponsive child for request 64232, in component <core> module <thread> Mon Sep 30 09:05:08 2013 : Error: WARNING: Unresponsive child for request 64233, in component <core> module <thread> Mon Sep 30 09:05:08 2013 : Error: WARNING: Unresponsive child for request 64234, in component <core> module <thread> Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64232 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64233 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64234 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64219 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64220 in component <core> module <thread>. Mon Sep 30 09:05:09 2013 : Info: WARNING: Child is hung for request 64221 in component <core> module <thread>. Mon Sep 30 09:05:10 2013 : Info: WARNING: Child is hung for request 64082 in component <core> module <thread>. Mon Sep 30 09:05:10 2013 : Info: WARNING: Child is hung for request 64083 in component <core> module <thread>. Mon Sep 30 09:05:10 2013 : Info: WARNING: Child is hung for request 64084 in component <core> module <thread>.
yes, our issue looked exactly like this. alan
Hi, i'll see if the current 2.2.x head does anything different (though none of the current known fixes against 2.2.1 appear to be dealing with proxying...) alan
Stefan Winter wrote:
I finally also found those on a 2.2.1 which runs a simple, proxy-mostly config. I would rather have expected such things on our complex internal instance, but well. Looks like:
Mon Sep 30 09:05:08 2013 : Error: WARNING: Unresponsive child for request 64232, in component <core> module <thread>
If you could narrow this down, it would be appreciated. Even a simple test case... The blockage seems to the input queue. i.e. requests are put into a queue for worker threads to pick up. If the worker threads never look at the queue, the requests get blocked. The code in threads.c did have some changes, but they shouldn't have affected this. Maybe you could try running 2.2.1 with version 8014870 of that file. If it doesn't have this problem, then there are only two commits to debug. Alan DeKok.
participants (4)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan Buxey
-
Alan DeKok -
Stefan Winter