!!! Assertion failed in listen.c, line 621 !!!
No way man! :) I've done a CVS clean install now (EVERYTHING old deleted before install and rebooted machine) but the same error occurs! It's just like the log from the previous post (below). radiusd dies after "Sending Access-Request" to the proxy, every single time. I'm not using any old conf, configured it from scratch. Please help! Thanks. On 12/11/06, Guilherme Franco <guilhermefranco@gmail.com> wrote:
Ok,
The log is below, thank you.
Gonna delete and clean install it, I just thought that "./configure, make, make install" would overwrite everything except the confs.
radiusd -xxx Mon Dec 11 19:47:58 2006 : Info: Ready to process requests. Mon Dec 11 19:47:58 2006 : Debug: Nothing to do. Sleeping until we see a request. Mon Dec 11 19:47:58 2006 : Debug: Thread 1 waiting to be assigned a request Mon Dec 11 19:47:58 2006 : Debug: Thread 2 waiting to be assigned a request Mon Dec 11 19:47:58 2006 : Debug: Thread 5 waiting to be assigned a request Mon Dec 11 19:47:58 2006 : Debug: Thread 3 waiting to be assigned a request Mon Dec 11 19:47:58 2006 : Debug: Thread 4 waiting to be assigned a request rad_recv: Access-Request packet from host 10.10.2.11 port 50000, id=206, length=234 Mon Dec 11 19:48:17 2006 : Debug: --- Walking the entire request list --- Mon Dec 11 19:48:17 2006 : Debug: Thread 1 got semaphore Mon Dec 11 19:48:17 2006 : Debug: Threads: total/active/spare threads = 5/0/5 Mon Dec 11 19:48:17 2006 : Debug: Thread 1 handling request 0, (1 handled so far) Mon Dec 11 19:48:17 2006 : Debug: Waking up in 1 seconds... User-Password = "bogus123" User-Name = "bogus@foo.com" Acct-Session-Id = "nas GigabitEthernet 11/0.165:2165:0028716608" Service-Type = Framed-User Framed-Protocol = PPP ERX-Pppoe-Description = "pppoe 00:0b:23:fd:1d:8c" Calling-Station-Id = "NAS-01#2165" NAS-Port-Type = Ethernet NAS-Port = 2952792181 NAS-Port-Id = "GigabitEthernet 11/0.165:2165" NAS-IP-Address = 10.10.2.11 NAS-Identifier = "NAS-01" Mon Dec 11 19:48:17 2006 : Debug: Processing the authorize section of radiusd.conf Mon Dec 11 19:48:17 2006 : Debug: modcall: entering group authorize for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "preprocess" returns ok for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling auth_log (rlm_detail) for request 0 Mon Dec 11 19:48:17 2006 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/10.10.2.11/auth-detail-20061211' Mon Dec 11 19:48:17 2006 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.10.2.11/auth-detail-20061211 Mon Dec 11 19:48:17 2006 : Debug: radius_xlat: 'Mon Dec 11 19:48:17 2006' Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from auth_log (rlm_detail) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "auth_log" returns ok for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "chap" returns noop for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "mschap" returns noop for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling unix (rlm_unix) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from unix (rlm_unix) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "unix" returns notfound for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Mon Dec 11 19:48:17 2006 : Debug: rlm_realm: Looking up realm "foo.com" for User-Name = "bogus@foo.com" Mon Dec 11 19:48:17 2006 : Debug: rlm_realm: Found realm "foo.com" Mon Dec 11 19:48:17 2006 : Debug: rlm_realm: Adding Stripped-User-Name = "bogus" Mon Dec 11 19:48:17 2006 : Debug: rlm_realm: Proxying request from user bogus to realm foo.com Mon Dec 11 19:48:17 2006 : Debug: rlm_realm: Adding Realm = "foo.com" Mon Dec 11 19:48:17 2006 : Debug: rlm_realm: Preparing to proxy authentication request to realm "foo.com" Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "suffix" returns updated for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Mon Dec 11 19:48:17 2006 : Debug: users: Matched entry DEFAULT at line 173 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "files" returns ok for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling sql (rlm_sql) for request 0 Mon Dec 11 19:48:17 2006 : Debug: radius_xlat: 'bogus@foo.com' Mon Dec 11 19:48:17 2006 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'bogus@foo.com' Mon Dec 11 19:48:17 2006 : Debug: rlm_sql (sql): Reserving sql socket id: 14 Mon Dec 11 19:48:17 2006 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'bogus@foo.com' ORDER BY id' Mon Dec 11 19:48:17 2006 : Debug: SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'bogus@foo.com' ORDER BY id Mon Dec 11 19:48:17 2006 : Debug: rlm_sql (sql): User found in radcheck table Mon Dec 11 19:48:17 2006 : Debug: radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'bogus@foo.com' ORDER BY id' Mon Dec 11 19:48:17 2006 : Debug: SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'bogus@foo.com' ORDER BY id Mon Dec 11 19:48:17 2006 : Debug: rlm_sql (sql): Released sql socket id: 14 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from sql (rlm_sql) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "sql" returns ok for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling expiration (rlm_expiration) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from expiration (rlm_expiration) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "expiration" returns noop for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling logintime (rlm_logintime) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from logintime (rlm_logintime) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "logintime" returns noop for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[authorize]: module "pap" returns noop for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall: group authorize returns updated for request 0 Mon Dec 11 19:48:17 2006 : Debug: Processing the pre-proxy section of radiusd.conf Mon Dec 11 19:48:17 2006 : Debug: modcall: entering group pre-proxy for request 0 Mon Dec 11 19:48:17 2006 : Debug: modsingle[pre-proxy]: calling pre_proxy_log (rlm_detail) for request 0 Mon Dec 11 19:48:17 2006 : Debug: radius_xlat: '/usr/local/var/log/radius/radacct/10.10.2.11/pre-proxy-detail-20061211' Mon Dec 11 19:48:17 2006 : Debug: rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/10.10.2.11/pre-proxy-detail-20061211 Mon Dec 11 19:48:17 2006 : Debug: radius_xlat: 'Mon Dec 11 19:48:17 2006' Mon Dec 11 19:48:17 2006 : Debug: modsingle[pre-proxy]: returned from pre_proxy_log (rlm_detail) for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall[pre-proxy]: module "pre_proxy_log" returns ok for request 0 Mon Dec 11 19:48:17 2006 : Debug: modcall: group pre-proxy returns ok for request 0 Mon Dec 11 19:48:17 2006 : Debug: proxy: allocating destination 30.30.2.1 port 1812 - Id 191 Sending Access-Request of id 191 to 30.30.2.1 port 1812 User-Password = "bogus123" User-Name = "bogus" Acct-Session-Id = "nas GigabitEthernet 11/0.165:2165:0028716608" Service-Type = Framed-User Framed-Protocol = PPP ERX-Pppoe-Description = "pppoe 00:0b:23:fd:1d:8c" Calling-Station-Id = "NAS-01#2165" NAS-Port-Type = Ethernet NAS-Port = 2952792181 NAS-Port-Id = "GigabitEthernet 11/0.165:2165" NAS-IP-Address = 10.10.2.11 NAS-Identifier = "NAS-01" Proxy-State = 0x323036 Mon Dec 11 19:48:17 2006 : Error: Assertion failed in listen.c, line 621
Guilherme Franco wrote:
I've done a CVS clean install now (EVERYTHING old deleted before install and rebooted machine) but the same error occurs!
OK... it's just that I have a difficult time reproducing the problem, so it's kind of hard to figure out what's going wrong. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
I have to thank you very much for all your effort! This is a very weird problem, but I remember that Peter Nixon kinda had the same problem. I saw that in the devel forum: http://lists.freeradius.org/mailman/htdig/freeradius-devel/2006-September/01... Also, from Tuyan: http://lists.freeradius.org/mailman/htdig/freeradius-devel/2006-September/01... And a similar one from Chaigneau, but with 1.1.3, without crashes: http://lists.freeradius.org/mailman/htdig/freeradius-devel/2006-November/010... If is there anything that I can do to help, please let me know. Thanks again! On 12/11/06, Alan DeKok <aland@deployingradius.com> wrote:
Guilherme Franco wrote:
I've done a CVS clean install now (EVERYTHING old deleted before install and rebooted machine) but the same error occurs!
OK... it's just that I have a difficult time reproducing the problem, so it's kind of hard to figure out what's going wrong.
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Tue 12 Dec 2006 03:08, Guilherme Franco wrote:
No way man!
:)
I've done a CVS clean install now (EVERYTHING old deleted before install and rebooted machine) but the same error occurs!
It's just like the log from the previous post (below).
radiusd dies after "Sending Access-Request" to the proxy, every single time.
I'm not using any old conf, configured it from scratch.
Please help!
Running CVS HEAD in single threaded mode works around the problem for the time being... This is on the TODO list to fix before the 2.0 release :-) http://wiki.freeradius.org/Development_Roadmap#Version_2.0 -- Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
Yes, I'm using it single-threaded, since September. I don't want to go back to 1.1.3 since it gave me problems. Thanks. On 12/12/06, Peter Nixon <listuser@peternixon.net> wrote:
On Tue 12 Dec 2006 03:08, Guilherme Franco wrote:
No way man!
:)
I've done a CVS clean install now (EVERYTHING old deleted before install and rebooted machine) but the same error occurs!
It's just like the log from the previous post (below).
radiusd dies after "Sending Access-Request" to the proxy, every single time.
I'm not using any old conf, configured it from scratch.
Please help!
Running CVS HEAD in single threaded mode works around the problem for the time being...
This is on the TODO list to fix before the 2.0 release :-)
http://wiki.freeradius.org/Development_Roadmap#Version_2.0
--
Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Peter Nixon wrote:
Running CVS HEAD in single threaded mode works around the problem for the time being...
Ugh. After staring at the code a little more, the bug is in threads.c, where it was passing 'request->proxysecret' rather than 'request' to the 'listener->send' function. It should be fixed now. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Thanks a lot! I gonna test it right now! On 12/12/06, Alan DeKok <aland@deployingradius.com> wrote:
Peter Nixon wrote:
Running CVS HEAD in single threaded mode works around the problem for the time being...
Ugh. After staring at the code a little more, the bug is in threads.c, where it was passing 'request->proxysecret' rather than 'request' to the 'listener->send' function.
It should be fixed now.
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
So, that was it! It works now, thanks. Back to the threads again :) On 12/12/06, Guilherme Franco <guilhermefranco@gmail.com> wrote:
Thanks a lot!
I gonna test it right now!
On 12/12/06, Alan DeKok <aland@deployingradius.com> wrote:
Peter Nixon wrote:
Running CVS HEAD in single threaded mode works around the problem for the time being...
Ugh. After staring at the code a little more, the bug is in threads.c, where it was passing 'request->proxysecret' rather than 'request' to the 'listener->send' function.
It should be fixed now.
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (3)
-
Alan DeKok -
Guilherme Franco -
Peter Nixon