Server exits without warning on radtest
HelloI'm facing a problem with the server. I set it and test it with a basic radtest and it exits without warning or error message.The last line is Thu Feb 21 08:33:14 2013 : Info: +- entering group authorize {...}So i guessed there was a problem in the very beginning of authorize, as the preprocess module doesn't output anything.But i couldn't find anything weird in the first lines :authorize { # The preprocess module takes care of sanitizing some bizarre # attributes in the request, and turning them into attributes # which are more standard. # # It takes care of processing the 'raddb/hints' and the # 'raddb/huntgroups' files. preprocessI didn't do big changes in the configuration files I only uncommented the sql related lines und set the SQL server info.Do you have an idea of the origin of the problem ?Here is the debug output of the server :Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and ! linkedThu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Attempting to connect to radius@localhost:/radiusThu Feb 21 08:33:10 2013 : Debug: rlm_sql (sql): starting 0Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0Thu Feb 21 08:33:10 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Connected new DB handle, #0Thu Feb 21 08:33:10 2013 : Debug: rlm_sql (sql): starting 1Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1Thu Feb 21 08:33:10 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Connected new DB handle, #1Thu Feb 21 08:33:10 2013 : Debug: rlm_sql (sql): starting 2Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2Thu Feb 21 08:33:10 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2Thu Feb 21 08:33:10 2013 : Info: rlm_sq! l (sql): Connected new DB handle, #2Thu Feb 21 08:33:10 2013 : Debug: rlm_sql (sql): starting 3Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3Thu Feb 21 08:33:10 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Connected new DB handle, #3Thu Feb 21 08:33:10 2013 : Debug: rlm_sql (sql): starting 4Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4Thu Feb 21 08:33:10 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4Thu Feb 21 08:33:10 2013 : Info: rlm_sql (sql): Connected new DB handle, #4Thu Feb 21 08:33:10 2013 : Debug: Module: Checking preacct {...} for more modules to loadThu Feb 21 08:33:10 2013 : Debug: (Loaded rlm_acct_unique, checking if it's valid)Thu Feb 21 08:33:10 2013 : Debug: Module: Linked to module rlm_acct_uniqueThu Feb 21 08:33:10 2013 : Debug: Module: Instantiating module "acct_unique" from file /etc/freeradius/modules/acct_uniqueThu Feb 21 08:33:10 2013 : Debug: ! acct_unique {Thu Feb 21 08:33:10 2013 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"Thu Feb 21 08:33:10 2013 : Debug: }Thu Feb 21 08:33:10 2013 : Debug: Module: Checking accounting {...} for more modules to loadThu Feb 21 08:33:10 2013 : Debug: (Loaded rlm_detail, checking if it's valid)Thu Feb 21 08:33:10 2013 : Debug: Module: Linked to module rlm_detailThu Feb 21 08:33:10 2013 : Debug: Module: Instantiating module "detail" from file /etc/freeradius/modules/detailThu Feb 21 08:33:10 2013 : Debug: detail {Thu Feb 21 08:33:10 2013 : Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"Thu Feb 21 08:33:10 2013 : Debug: header = "%t"Thu Feb 21 08:33:10 2013 : Debug: detailperm = 384Thu Feb 21 08:33:10 2013 : Debug: dirperm = 493Thu Feb 21 08:33:10 2013 : Debug: locking = noThu Feb 21 08:33:10 2013 : Debug: log_packet_header = noThu Feb 21 08:33:10 2013 : Debug: }T! hu Feb 21 08:33:10 2013 : Debug: Module: Instantiating module "attr_f ilter.accounting_response" from file /etc/freeradius/modules/attr_filterThu Feb 21 08:33:10 2013 : Debug: attr_filter attr_filter.accounting_response {Thu Feb 21 08:33:10 2013 : Debug: attrsfile = "/etc/freeradius/attrs.accounting_response"Thu Feb 21 08:33:10 2013 : Debug: key = "%{User-Name}"Thu Feb 21 08:33:10 2013 : Debug: relaxed = noThu Feb 21 08:33:10 2013 : Debug: }Thu Feb 21 08:33:10 2013 : Debug: Module: Checking session {...} for more modules to loadThu Feb 21 08:33:10 2013 : Debug: Module: Checking post-proxy {...} for more modules to loadThu Feb 21 08:33:10 2013 : Debug: Module: Checking post-auth {...} for more modules to loadThu Feb 21 08:33:10 2013 : Debug: } # modulesThu Feb 21 08:33:10 2013 : Debug: } # serverThu Feb 21 08:33:10 2013 : Debug: radiusd: #### Opening IP addresses and Ports ####Thu Feb 21 08:33:10 2013 : Debug: listen {Thu Feb 21 08:33:10 2013 : Debug: type = "auth"Thu Feb 21 08:33:10 2013 : Debug: ipaddr = *Thu Feb 2! 1 08:33:10 2013 : Debug: port = 0Thu Feb 21 08:33:10 2013 : Debug: }Thu Feb 21 08:33:10 2013 : Debug: listen {Thu Feb 21 08:33:10 2013 : Debug: type = "acct"Thu Feb 21 08:33:10 2013 : Debug: ipaddr = *Thu Feb 21 08:33:10 2013 : Debug: port = 0Thu Feb 21 08:33:10 2013 : Debug: }Thu Feb 21 08:33:10 2013 : Debug: listen {Thu Feb 21 08:33:10 2013 : Debug: type = "auth"Thu Feb 21 08:33:10 2013 : Debug: ipaddr = 127.0.0.1Thu Feb 21 08:33:10 2013 : Debug: port = 18120Thu Feb 21 08:33:10 2013 : Debug: }Thu Feb 21 08:33:10 2013 : Debug: Listening on authentication address * port 1812Thu Feb 21 08:33:10 2013 : Debug: Listening on accounting address * port 1813Thu Feb 21 08:33:10 2013 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnelThu Feb 21 08:33:10 2013 : Debug: Listening on proxy address * port 1814Thu Feb 21 08:33:10 2013 : Info: Ready to process requests.rad_recv: Access-Request packet from host 127.0.0.1 port 4! 3468, id=182, length=56 User-Name = "jean" User-Password = "pw" NAS-IP-Address = 127.0.1.1 NAS-Port = 0Thu Feb 21 08:33:14 2013 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/defaultThu Feb 21 08:33:14 2013 : Info: +- entering group authorize {...}Thank you
Le 22.02.2013 09:30, Adrien Morvan a écrit :
Hello
I'm facing a problem with the server. I set it and test it with a basic radtest and it exits without warning or error message. The last line is Thu Feb 21 08:33:14 2013 : Info: +- entering group authorize {...}
So i guessed there was a problem in the very beginning of authorize, as the preprocess module doesn't output anything. But i couldn't find anything weird in the first lines :
authorize {
# The prepro cess module takes care of sanitizing some bizarre # attributes in the request, and turning them into attributes # which are more standard. # # It takes care of processing the 'raddb/hints' and the # 'raddb/huntgroups' files. preprocess
I didn't do big changes in the configuration files I only uncommented the sql related lines und set the SQL server info. Do you have an idea of the origin of the problem ?
Weird indeed. What version are you running on which OS (don't strip the beginning of the debug output, it gives at least Freeradius version) And try to run it within gdb. see doc/bugs Olivier
participants (2)
-
Adrien Morvan -
Olivier Beytrison