latest CVS 2.0 beta hang problem
hi, a 2.0 beta (latest CVS head) install server locked up on us today in its early test deployment case secnario a request was proxied off to another RADIUS server. no response came back. server totally fails to respond to anything else. the only entry in the 'radiusd -X' is the last 2 lines Fri Jan 4 13:40:23 2008 : Error: Rejecting request 12643 due to lack of any response from home server 10.1.2.3 port 1812 Fri Jan 4 13:40:23 2008 : Error: WARNING: Unresponsive child (id 0) for request 12643, in module <server-core> component <server-core> thats all. no further debug i'm afraid. alan
A.L.M.Buxey@lboro.ac.uk wrote:
a 2.0 beta (latest CVS head) install server locked up on us today in its early test deployment
Ugh.
case secnario
a request was proxied off to another RADIUS server. no response came back. server totally fails to respond to anything else. the only entry in the 'radiusd -X' is the last 2 lines
I'll go look at that tomorrow. If I can reproduce it, it should be easy to fix. Alan DeKok.
Hi,
a 2.0 beta (latest CVS head) install server locked up on us today in its early test deployment
Ugh.
case secnario
a request was proxied off to another RADIUS server. no response came back. server totally fails to respond to anything else. the only entry in the 'radiusd -X' is the last 2 lines
I'll go look at that tomorrow. If I can reproduce it, it should be easy to fix.
*correction* thats the last 2 output lines from radiusd.log i dont have a radiusd -X output - i will see if i can trigger this behaviour with eg radtest or an EAP session on another test server. the issue doesnt occur with 2.0.0-pre2 PS by default in latest CVS, the server logs a lot less to radiusd.log (eg auth OK, auth fail etc - i have logging set to yes int he config but still no output) whats the required config change to get the 'old behaviour' back? alan
A.L.M.Buxey@lboro.ac.uk wrote:
*correction* thats the last 2 output lines from radiusd.log i dont have a radiusd -X output - i will see if i can trigger this behaviour with eg radtest or an EAP session on another test server. the issue doesnt occur with 2.0.0-pre2
A lot has changed since -pre2.
PS by default in latest CVS, the server logs a lot less to radiusd.log (eg auth OK, auth fail etc - i have logging set to yes int he config but still no output) whats the required config change to get the 'old behaviour' back?
Hmm... it *should* be configurable in radiusd.conf. See the "log" section in radiusd.conf. Some configuration items have moved, because it was dumb to have "log_foo", "log_bar", "log_baz", etc. Alan DeKok.
hi, okay - got it to do the same with a straight radtest. here is the radiusd -X - several attempts that get proxied away..and never answered. remote site marked as zombie but then any valid requests just dont get serviced. Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Proxy-State = 0x3930 Proxying request 0 to home server 10.1.2.3 port 1812 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Going to the next request Waking up in 0.9 seconds. Waking up in 28.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=90, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 14 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Waking up in 26.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=90, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 14 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Waking up in 23.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=90, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 14 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Waking up in 20.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=90, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 14 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Waking up in 17.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=90, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 14 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Waking up in 14.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=90, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 14 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Waking up in 11.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=90, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 14 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Waking up in 8.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=90, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 14 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Waking up in 5.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=90, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 14 Sending Access-Request of id 14 to 10.1.2.3 port 1812 User-Name = "testuser1@foo.bar" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testuser1" Realm = "test1" Realm = "test1" Proxy-State = 0x3930 Waking up in 2.9 seconds. Rejecting request 0 due to lack of any response from home server 10.1.2.3 port 1812 WARNING: Unresponsive child (id 0) for request 0, in module <server-core> component <server-core> Found Post-Proxy-Type Going to the next request WARNING: Marking home server 10.1.2.3 port 1812 as zombie (it looks like it is dead). Waking up in 0.2 seconds. Child is finally responsive for request 0 after this, its a kill -9 job too on the server process. not just kill/killall or server restart via 'service' init.d tool. alan
A.L.M.Buxey@lboro.ac.uk wrote:
okay - got it to do the same with a straight radtest. here is the radiusd -X - several attempts that get proxied away..and never answered. remote site marked as zombie but then any valid requests just dont get serviced.
OK. There are a few issues:
Rejecting request 0 due to lack of any response from home server 10.1.2.3 port 1812 WARNING: Unresponsive child (id 0) for request 0, in module <server-core> component <server-core> Found Post-Proxy-Type
That's just a dumb message, as it's not running in threaded mode, AND the request isn't being process in a child thread! I've committed a fix which prints that message only if there is really a child thread that's unresponsive.
Going to the next request WARNING: Marking home server 10.1.2.3 port 1812 as zombie (it looks like it is dead). Waking up in 0.2 seconds. Child is finally responsive for request 0
after this, its a kill -9 job too on the server process. not just kill/killall or server restart via 'service' init.d tool.
I think what's happening is that the request is being free'd in a place where it doesn't expect it to be free'd. I've re-arranged the code to note, and catch this race condition. It works in my tests, but my tests didn't see this race condition in the first place... Alan DeKok.
hi, okay - updated to latest CVS after I saw the CVS log messages regarding this proxying issue. things look a little better but at the end the server is dead - unable to respond to any legitimate requests - (ie even simple local non proxy ones) latest output: Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Proxy-State = 0x33 Proxying request 0 to home server 10.1.2.3 port 1812 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Going to the next request Waking up in 0.9 seconds. Waking up in 28.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=3, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 108 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Waking up in 26.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=3, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 108 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Waking up in 23.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=3, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 108 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Waking up in 20.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=3, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 108 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Waking up in 17.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=3, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 108 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Waking up in 14.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=3, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 108 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Waking up in 11.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=3, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 108 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Waking up in 8.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=3, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 108 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Waking up in 5.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 32772, id=3, length=66 Sending duplicate proxied request to home server 10.1.2.3 port 1812 - ID: 108 Sending Access-Request of id 108 to 10.1.2.3 port 1812 User-Name = "testuser1@testdomain.org" User-Password = "testing123" NAS-IP-Address = 10.1.2.2 NAS-Port = 1812 Huntgroup-Name = "testhunt" Realm = "testrealm" Realm = "testrealm" Proxy-State = 0x33 Waking up in 2.9 seconds. Rejecting request 0 due to lack of any response from home server 10.1.2.3 port 1812 Found Post-Proxy-Type +- entering group Fail expand: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d -> /var/log/radius/radacct/127.0.0.1/detail-20080105 rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/radius/radacct/127.0.0.1/detail-20080105 expand: %t -> Sat Jan 5 13:10:19 2008 rlm_detail: Freeradius-Proxied-To = 10.1.2.3 ++[detail] returns ok There was no response configured: rejecting request 0 Found Post-Auth-Type Reject +- entering group REJECT expand: %{User-Name} -> testuser1@testdomain.org attr_filter: Matched entry DEFAULT at line 11 ++[attr_filter.access_reject] returns updated Sending Access-Reject of id 3 to 127.0.0.1 port 32772 Finished request 0. Going to the next request WARNING: Marking home server 10.1.2.3 port 1812 as zombie (it looks like it is dead). Waking up in 1.9 seconds. then nothing out of the server. PS a little note. there are 2 other home servers configured in the proxy realm that this request could go to - the server at no point seems to want to talk to the other 2 home servers either. alan
A.L.M.Buxey@lboro.ac.uk wrote:
okay - updated to latest CVS after I saw the CVS log messages regarding this proxying issue. things look a little better but at the end the server is dead - unable to respond to any legitimate requests - (ie even simple local non proxy ones)
Please use 'gdb' to attach to the process and find out what it's doing (see doc/bugs). I don't know what OS you're running, and I can't reproduce the issue myself. So I'm *completely* stuck at this point. ...
WARNING: Marking home server 10.1.2.3 port 1812 as zombie (it looks like it is dead). Waking up in 1.9 seconds.
then nothing out of the server.
It's doing *something*. Is it using all of the available CPU? Can you run it in debugging mode under valgrind? $ valgrind --tool=memcheck radiusd -X and see what it prints out.
PS a little note. there are 2 other home servers configured in the proxy realm that this request could go to - the server at no point seems to want to talk to the other 2 home servers either.
That's fine. The request is reaching "max_request_time" at this point, too. It can't be proxied anywhere else, because it's used all of it's available time. Alan DeKok.
A.L.M.Buxey@lboro.ac.uk wrote:
PS a little note. there are 2 other home servers configured in the proxy realm that this request could go to - the server at no point seems to want to talk to the other 2 home servers either.
If you want the request sent to another home server, set "response_window" in the "home_server" config to be less than "max_request_time". e.g. 20 and 30. If the first server is dead, the request SHOULD be sent to the next server. Alan DeKok.
Hi,
A lot has changed since -pre2.
Hmm... it *should* be configurable in radiusd.conf. See the "log" section in radiusd.conf. Some configuration items have moved, because it was dumb to have "log_foo", "log_bar", "log_baz", etc.
ha! a lot HAS been changing. damn. you are right. how did i miss that fundamental change to the log {} section. ??? crazy. anyway, i have now moved all the pre-2 log stuff log_auth, log_file etc etc into the correct single log {} stanza and removed the legacy log_ prefix which each entry had. its all working fine now. there was another post by someone else on this list a while back about latest CVS being more quiet than the old. perhaps this needs to be highlighted a little better - perhaps have somehting in the startup parser that can detect these old legacy configs and spew out a warning? in 'the old days' the log_ entries could lie anywhere in radiusd.conf - really should only be in log {} and no entries should start with log_ ...... ah! but they do. we have a small oddity log_destination = files surely this should also be cleared into the log {} stanza? eg log { destination = files } sorry for the false alert and thanks for the pointer/tip to getting this little issue sorted. alan
A.L.M.Buxey@lboro.ac.uk wrote:
ha! a lot HAS been changing. damn. you are right. how did i miss that fundamental change to the log {} section. ???
It got changed fairly recently.
there was another post by someone else on this list a while back about latest CVS being more quiet than the old. perhaps this needs to be highlighted a little better - perhaps have somehting in the startup parser that can detect these old legacy configs and spew out a warning?
I just updated the code so that the parsing of entries is re-arranged a bit. It means that old configurations with "log_foo" will still use *those* definitions. So other people with the same kind of config won't suddenly see the logs get quieter.
we havea small oddity
log_destination = files
surely this should also be cleared into the log {} stanza? eg
Likely, yes.
log { destination = files }
sorry for the false alert and thanks for the pointer/tip to getting this little issue sorted.
It's a usability issue that was easy to fix. Alan DeKok.
participants (2)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok