info: WARNING: Child is hung for request XXXX in component <core> module (2.2.5)
Hi we regulary get these messages since we upgraded from 2.2.3 to 2.2.5 I have attached the GDB log as i'm no developper expert to find out what's going on... Hopefully someone can help us out with this <SOME INFO> We are running Debian 7.7 x64 Linux 3.2.0-4-amd64 (radius1) 10/22/2014 _x86_64_ (8 CPU) avg-cpu: %user %nice %system %iowait %steal %idle 0.24 0.00 0.11 0.10 0.00 99.56 Device: tps kB_read/s kB_wrtn/s kB_read kB_wrtn cciss/c0d0 163.25 9.31 1491.34 3263611 522909360 <RADIUS LOGS> Wed Oct 22 16:35:35 2014 : Error: Discarding duplicate request from client telenet-81.82.0.0/15 port 3072 - ID: 226 due to unfinished request 2664227 Wed Oct 22 16:35:37 2014 : Error: WARNING: Unresponsive thread 2664227 for request 0, in component <core> module Wed Oct 22 16:35:38 2014 : Info: WARNING: Child is hung for request 2664227 in component <core> module . Attached a debug with command, "echo 'thread apply all bt full' > /tmp/gdb_cmd; gdb --pid `cat /var/run/freeradius/freeradius.pid` -batch -x /tmp/gdb_cmd > gdb_bt; gzip gdb_bt" Hopefully this brings something useful, as previous debug to devel list didnt show the reason.
Hi list, i've just upgraded our server to 2.2.6 in the hope our child hung would be fixed. The problem we are having is that whenever a radius proxy server (outside of our control: eduroam national home server) doesn't respond in time, we get the following messages blocking freeradius: Fri Nov 21 17:02:07 2014 : Error: Internal sanity check failed for child state <= NEW MESSAGE since 2.2.6 Fri Nov 21 17:02:07 2014 : Error: Reply from home server A.B.C.D port 1812 - ID: 84 arrived too late for request 11986. Try increasing 'retry_delay' or 'max_request_time' Fri Nov 21 17:02:18 2014 : Error: WARNING: Unresponsive thread 11986 for request 0, in component <core> module Fri Nov 21 17:02:19 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module . Fri Nov 21 17:02:20 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module . Fri Nov 21 17:02:23 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module . Fri Nov 21 17:02:26 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module . Fri Nov 21 17:02:31 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module . Fri Nov 21 17:02:39 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module . Fri Nov 21 17:02:50 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module . Fri Nov 21 17:03:07 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module . Fri Nov 21 17:03:33 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module . Config: # # This configuration file handles the requests to the EDUROAM community # home_server roaming1-v4 { # type = auth+acct type = auth ipaddr = A.B.C.D1 port = 1812 secret = secretABCD1 require_message_authenticator = yes status_check = status-server check_interval = 30 response_window = 20 zombie_period = 40 num_answers_to_alive = 3 max_request_time = 5 } home_server roaming2-v4 { # type = auth+acct type = auth ipaddr = A.B.C.D2 port = 1812 secret = secretABCD2 require_message_authenticator = yes status_check = status-server check_interval = 30 response_window = 20 zombie_period = 40 num_answers_to_alive = 3 max_request_time = 5 } home_server_pool EDUROAM { type = client-port-balance home_server = roaming1-v4 home_server = roaming2-v4 virtual_server = eduroam } realm LOCAL { # If we do not specify a server pool, the realm is LOCAL, and # requests are not proxied. } realm NULL { # If we do not specify a server pool, the realm is LOCAL, and # requests are not proxied. } # Match-any/previous DEFAULT realm statement realm "~.+$" { # pool = EDUROAM auth_pool = EDUROAM nostrip } On Wed, Oct 22, 2014 at 4:38 PM, Jonathan <huffelduffel@gmail.com> wrote:
Hi we regulary get these messages since we upgraded from 2.2.3 to 2.2.5
I have attached the GDB log as i'm no developper expert to find out what's going on...
Hopefully someone can help us out with this
<SOME INFO>
We are running Debian 7.7 x64
Linux 3.2.0-4-amd64 (radius1) 10/22/2014 _x86_64_ (8 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle 0.24 0.00 0.11 0.10 0.00 99.56
Device: tps kB_read/s kB_wrtn/s kB_read kB_wrtn cciss/c0d0 163.25 9.31 1491.34 3263611 522909360
<RADIUS LOGS> Wed Oct 22 16:35:35 2014 : Error: Discarding duplicate request from client telenet-81.82.0.0/15 port 3072 - ID: 226 due to unfinished request 2664227 Wed Oct 22 16:35:37 2014 : Error: WARNING: Unresponsive thread 2664227 for request 0, in component <core> module Wed Oct 22 16:35:38 2014 : Info: WARNING: Child is hung for request 2664227 in component <core> module .
Attached a debug with command, "echo 'thread apply all bt full' > /tmp/gdb_cmd; gdb --pid `cat /var/run/freeradius/freeradius.pid` -batch -x /tmp/gdb_cmd > gdb_bt; gzip gdb_bt"
Hopefully this brings something useful, as previous debug to devel list didnt show the reason.
Hi, only 2 proxies so not UK ;-)
# Match-any/previous DEFAULT realm statement realm "~.+$" { # pool = EDUROAM auth_pool = EDUROAM nostrip }
urgh, are you doing other unlang filttering? if not you will be sending all kinds of junk upstream which is likely to be dropped/discarded...maybe silently or maybe rejected - either way, you are likely to be triggering the status-server far more than needed. if you are sending RADISU requests off-site then you have to be wary that other sites may not respond quickly... and ensure that any NAS/RADIUSserver timeouts in your pipeline are adjusted accoridngly - expect the reponse time to be more than a secnd or 2 - default on some kit is like 2 or 3 seconds...may need to extend that to eg 5 seconds otherwise your NAS will retransmit the request (hence duplicates) - also ensure you arent cleaning up requests to quickly...or they'll be removed from the system before the response has come back..end therefore fail. alan
A.L.M.Buxey@lboro.ac.uk wrote:
urgh, are you doing other unlang filttering? if not you will be sending all kinds of junk upstream which is likely to be dropped/discarded...maybe silently or maybe rejected - either way, you are likely to be triggering the status-server far more than needed.
Yeah... though that's really an eduroam question. Eduroam *should* supply a list of allowed domains. Packets for those domains get proxied, everything else gets dropped. i.e. if someone logs into eduroam as "bill@microsoft.com", you KNOW that it's not supposed to get proxied. If you do proxy it, the upstream servers are likely to drop it... and due to RADIUS issues, you'll think that those proxies are down. Alan DeKok.
Eduroam *should* supply a list of >allowed domains. Packets for those >domains get proxied, everything else >gets dropped.
Intra federated system so how do people know all the available realms worldwide (huge list) and realms are being added all the time.. admins don't want to change their config all the time . The initial rule is that sites should ensure the username has a valid construct before sending it upstream eg NAI format, with @ , no spaces in realm, no double dots, illegal characters etc. Check logs for typos of your own domain and drop those too (and contact the affected users! ) however, some federations go the extra mile and tell their community a black list of realms - that is a much shorter list of very common realms that won't work on eduroam However I do recall a discussion we had about a RADIUS-based realm routing protocol many many years ago.... ;) alan
Alan Buxey wrote:
Eduroam *should* supply a list of >allowed domains. Packets for those domains get proxied, everything else >gets dropped.
Intra federated system so how do people know all the available realms worldwide (huge list) and realms are being added all the time.. admins don't want to change their config all the time .
The initial rule is that sites should ensure the username has a valid construct before sending it upstream eg NAI format, with @ , no spaces in realm, no double dots, illegal characters etc. Check logs for typos of your own domain and drop those too (and contact the affected users! ) however, some federations go the extra mile and tell their community a black list of realms - that is a much shorter list of very common realms that won't work on eduroam
However I do recall a discussion we had about a RADIUS-based realm routing protocol many many years ago.... ;)
alan
------------------------------------------------------------------------
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Alan Buxey wrote:
Intra federated system so how do people know all the available realms worldwide (huge list) and realms are being added all the time.. admins don't want to change their config all the time .
The national proxies could know. That wouldn't be too complicated. And it would help, because they could just reject packets for nonsense destinations.
However I do recall a discussion we had about a RADIUS-based realm routing protocol many many years ago.... ;)
Yeah... no one cares. Happily, however, I have other solutions in the works. Alan DeKok.
Hi,
only 2 proxies so not UK ;-)
It is Belgium :)
# Match-any/previous DEFAULT realm statement realm "~.+$" { # pool = EDUROAM auth_pool = EDUROAM nostrip }
urgh, are you doing other unlang filttering? if not you will be sending all kinds of junk upstream which is likely to be dropped/discarded...maybe silently or maybe rejected - either way, you are likely to be triggering the status-server far more than needed.
I perform a sanity check with filter_username before sending anything else out.
if you are sending RADISU requests off-site then you have to be wary that other sites may not respond quickly... and ensure that any NAS/RADIUSserver timeouts in your pipeline are adjusted accoridngly - expect the reponse time to be more than a secnd or 2 - default on some kit is like 2 or 3 seconds...may need to extend that to eg 5 seconds otherwise your NAS will retransmit the request (hence duplicates) - also ensure you arent cleaning up requests to quickly...or they'll be removed from the system before the response has come back..end therefore fail.
We have a the following global parameters: max_request_time=30 cleanup_delay=5 But override per home-server with max_request_time=5 (i want to reject proxy requests which take longer then 5 seconds to reply as it's probably bogus anyway then or just a real terribly slow responding radius server )
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Jonathan wrote:
The problem we are having is that whenever a radius proxy server (outside of our control: eduroam national home server) doesn't respond in time, we get the following messages blocking freeradius:
Fri Nov 21 17:02:07 2014 : Error: Internal sanity check failed for child state <= NEW MESSAGE since 2.2.6
That means the following has happened: - the server proxied a request to a home server - eventually, the server gives up, and uses Post-Proxy-Type Fail - while it's running that, the home server replies.
Fri Nov 21 17:02:07 2014 : Error: Reply from home server A.B.C.D port 1812 - ID: 84 arrived too late for request 11986. Try increasing 'retry_delay' or 'max_request_time' Fri Nov 21 17:02:18 2014 : Error: WARNING: Unresponsive thread 11986 for request 0, in component <core> module Fri Nov 21 17:02:19 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module .
That's wrong... it means that the request isn't being processed through a module, BUT the server core thinks that a thread is still processing it. Hmm... please try the v2.x.x branch: https://github.com/FreeRADIUS/freeradius-server/archive/v2.x.x.zip I've found one thing which makes me go "Huh?" Hopefully that should fix it. Alan DeKok.
That means the following has happened:
- the server proxied a request to a home server - eventually, the server gives up, and uses Post-Proxy-Type Fail - while it's running that, the home server replies.
Fri Nov 21 17:02:07 2014 : Error: Reply from home server A.B.C.D port 1812 - ID: 84 arrived too late for request 11986. Try increasing 'retry_delay' or 'max_request_time' Fri Nov 21 17:02:18 2014 : Error: WARNING: Unresponsive thread 11986 for request 0, in component <core> module Fri Nov 21 17:02:19 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module .
That's wrong... it means that the request isn't being processed through a module, BUT the server core thinks that a thread is still processing it.
Hmm... please try the v2.x.x branch:
https://github.com/FreeRADIUS/freeradius-server/archive/v2.x.x.zip
I've found one thing which makes me go "Huh?"
Hopefully that should fix it.
Ok, I'll give this a try and hope this helps
Hi alan, I've downloaded https://github.com/FreeRADIUS/freeradius-server/archive/v2.x.x.zip and performed a diff against 2.2.6 but seems the patch is missing: diff -urN freeradius-server-2.2.6/debian/changelog freeradius-server-2.x.x/debian/changelog --- freeradius-server-2.2.6/debian/changelog 2014-11-18 20:56:52.000000000 +0100 +++ freeradius-server-2.x.x/debian/changelog 2014-11-18 21:32:11.000000000 +0100 @@ -1,3 +1,9 @@ +freeradius (2.2.7+git) unstable; urgency=medium + + * New upstream version. + + -- Arran Cudbard-Bell <a.cudbardb@freeradius.org> Tue, 18 Nov 2014 11:35:00 +0100 + freeradius (2.2.6+git) unstable; urgency=medium * New upstream version. diff -urN freeradius-server-2.2.6/doc/ChangeLog freeradius-server-2.x.x/doc/ChangeLog --- freeradius-server-2.2.6/doc/ChangeLog 2014-11-18 20:56:52.000000000 +0100 +++ freeradius-server-2.x.x/doc/ChangeLog 2014-11-18 21:32:11.000000000 +0100 @@ -1,3 +1,8 @@ +FreeRADIUS 2.2.7 Tuesday 18 Nov 2014 14:00:00 EST, urgency=medium + Feature improvements + + Bug fixes + FreeRADIUS 2.2.6 Tuesday 18 Nov 2014 15:00:00 EST, urgency=medium Feature improvements * When supported by OpenSSL, allow TLS 1.1 and TLS 1.2 diff -urN freeradius-server-2.2.6/redhat/freeradius.spec freeradius-server-2.x.x/redhat/freeradius.spec --- freeradius-server-2.2.6/redhat/freeradius.spec 2014-11-18 20:56:52.000000000 +0100 +++ freeradius-server-2.x.x/redhat/freeradius.spec 2014-11-18 21:32:11.000000000 +0100 @@ -1,6 +1,6 @@ Summary: High-performance and highly configurable free RADIUS server Name: freeradius -Version: 2.2.6 +Version: 2.2.7 Release: 1%{?dist} License: GPLv2+ and LGPLv2+ Group: System Environment/Daemons diff -urN freeradius-server-2.2.6/suse/freeradius.spec freeradius-server-2.x.x/suse/freeradius.spec --- freeradius-server-2.2.6/suse/freeradius.spec 2014-11-18 20:56:52.000000000 +0100 +++ freeradius-server-2.x.x/suse/freeradius.spec 2014-11-18 21:32:11.000000000 +0100 @@ -5,7 +5,7 @@ Name: freeradius-server -Version: 2.2.6 +Version: 2.2.7 Release: 0 License: GPLv2 ; LGPLv2.1 Group: Productivity/Networking/Radius/Servers diff -urN freeradius-server-2.2.6/VERSION freeradius-server-2.x.x/VERSION --- freeradius-server-2.2.6/VERSION 2014-11-18 20:56:52.000000000 +0100 +++ freeradius-server-2.x.x/VERSION 2014-11-18 21:32:11.000000000 +0100 @@ -1 +1 @@ -2.2.6 On Sat, Nov 22, 2014 at 9:38 AM, Jonathan <huffelduffel@gmail.com> wrote:
That means the following has happened:
- the server proxied a request to a home server - eventually, the server gives up, and uses Post-Proxy-Type Fail - while it's running that, the home server replies.
Fri Nov 21 17:02:07 2014 : Error: Reply from home server A.B.C.D port 1812 - ID: 84 arrived too late for request 11986. Try increasing 'retry_delay' or 'max_request_time' Fri Nov 21 17:02:18 2014 : Error: WARNING: Unresponsive thread 11986 for request 0, in component <core> module Fri Nov 21 17:02:19 2014 : Info: WARNING: Child is hung for request 11986 in component <core> module .
That's wrong... it means that the request isn't being processed through a module, BUT the server core thinks that a thread is still processing it.
Hmm... please try the v2.x.x branch:
https://github.com/FreeRADIUS/freeradius-server/archive/v2.x.x.zip
I've found one thing which makes me go "Huh?"
Hopefully that should fix it.
Ok, I'll give this a try and hope this helps
Not everything is put into the changelog and things get collated later when the release comes out. If you do a full diff or use git with 'whatchanged' you'll see the differences alan
participants (4)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan Buxey
-
Alan DeKok -
Jonathan