Duplicate entries and incorrect accounting and authorization
I was using freeradius 1.05 with MYSQL 4.0 without any problems. I've upgraded the OS in my server (freebsd 5.1 to 6.0), upgraded to freeradius 1.10 and MySQL 4.1, copied the previous working raddb directory, initially preserving the same configuration files and I couldn't get things working back again. Basically I've got duplicate entries in radpostauth, no entries in radacct and the NAS does not recognize the successful authentication even though from the radius server point of view it seems to get authentication right. I've read the FAQ (my server has a single NIC), docs in the release (before, I was using the sqlcounter module but now I've decided to remove it since radiusd.conf already has the dailycounter and monthlycounter functionality that I needed) but still I can not get it right. Here's the relevant info: ............................................ root@rds# /usr/local/sbin/radiusd -X -y Starting - reading configuration files ... reread_config: reading radiusd.conf Config: including file: /usr/local/etc/raddb/proxy.conf Config: including file: /usr/local/etc/raddb/clients.conf Config: including file: /usr/local/etc/raddb/snmp.conf Config: including file: /usr/local/etc/raddb/sql.conf main: prefix = "/usr/local" main: localstatedir = "/var" main: logdir = "/var/log" main: libdir = "/usr/local/lib" main: radacctdir = "/var/log/radacct" main: hostname_lookups = no main: max_request_time = 30 main: cleanup_delay = 5 main: max_requests = 1024 main: delete_blocked_requests = 0 main: port = 0 main: allow_core_dumps = no main: log_stripped_names = no main: log_file = "/var/log/radius.log" main: log_auth = yes main: log_auth_badpass = no main: log_auth_goodpass = no main: pidfile = "/var/run/radiusd/radiusd.pid" main: bind_address = YYY.YYY.YYY.YYY IP address [YYY.YYY.YYY.YYY] main: user = "(null)" main: group = "(null)" main: usercollide = no main: lower_user = "no" main: lower_pass = "no" main: nospace_user = "no" main: nospace_pass = "no" main: checkrad = "/usr/local/sbin/checkrad" main: proxy_requests = yes proxy: retry_delay = 5 proxy: retry_count = 3 proxy: synchronous = no proxy: default_fallback = yes proxy: dead_time = 120 proxy: post_proxy_authorize = no proxy: wake_all_if_all_dead = no security: max_attributes = 200 security: reject_delay = 1 security: status_server = no main: debug_level = 0 read_config_files: reading dictionary read_config_files: reading naslist read_config_files: reading clients read_config_files: reading realms radiusd: entering modules setup Module: Library search path is /usr/local/lib Module: Loaded expr Module: Instantiated expr (expr) Module: Loaded PAP pap: encryption_scheme = "crypt" Module: Instantiated pap (pap) Module: Loaded CHAP Module: Instantiated chap (chap) Module: Loaded MS-CHAP mschap: use_mppe = yes mschap: require_encryption = no mschap: require_strong = no mschap: with_ntdomain_hack = no mschap: passwd = "(null)" mschap: authtype = "MS-CHAP" mschap: ntlm_auth = "(null)" Module: Instantiated mschap (mschap) Module: Loaded System unix: cache = no unix: passwd = "(null)" unix: shadow = "(null)" unix: group = "(null)" unix: radwtmp = "/var/log/radwtmp" unix: usegroup = no unix: cache_reload = 600 Module: Instantiated unix (unix) Module: Loaded preprocess preprocess: huntgroups = "/usr/local/etc/raddb/huntgroups" preprocess: hints = "/usr/local/etc/raddb/hints" preprocess: with_ascend_hack = no preprocess: ascend_channels_per_line = 23 preprocess: with_ntdomain_hack = no preprocess: with_specialix_jetstream_hack = no preprocess: with_cisco_vsa_hack = no Module: Instantiated preprocess (preprocess) Module: Loaded detail detail: detailfile = "/var/log/radacct/%{Client-IP-Address}/auth- detail-%Y%m%d" detail: detailperm = 384 detail: dirperm = 493 detail: locking = no Module: Instantiated detail (auth_log) Module: Loaded realm realm: format = "suffix" realm: delimiter = "@" realm: ignore_default = no realm: ignore_null = no Module: Instantiated realm (suffix) Module: Loaded SQL sql: driver = "rlm_sql_mysql" sql: server = "localhost" sql: port = "" sql: login = "root" sql: password = "password" sql: radius_db = "radius" sql: acct_table = "radacct" sql: acct_table2 = "radacct" sql: authcheck_table = "radcheck" sql: authreply_table = "radreply" sql: groupcheck_table = "radgroupcheck" sql: groupreply_table = "radgroupreply" sql: usergroup_table = "usergroup" sql: nas_table = "nas" sql: dict_table = "dictionary" sql: sqltrace = yes sql: sqltracefile = "/var/log/sqltrace.sql" sql: readclients = no sql: deletestalesessions = yes sql: num_sql_socks = 5 sql: sql_user_name = "%{User-Name}" sql: default_user_profile = "" sql: query_on_not_found = no sql: authorize_check_query = "SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = '%{SQL- User-Name}' ORDER BY id" sql: authorize_reply_query = "SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = '%{SQL- User-Name}' ORDER BY id" sql: authorize_group_check_query = "SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,rad groupcheck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id" sql: authorize_group_reply_query = "SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,rad groupreply.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id" sql: accounting_onoff_query = "UPDATE radacct SET AcctStopTime='%S', AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime), AcctTerminateCause='%{Acct-Terminate- Cause}', AcctStopDelay = '%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND NASIPAddress= '%{NAS-IP- Address}' AND AcctStartTime <= '%S'" sql: accounting_update_query = "UPDATE radacct SET FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input- Octets}', AcctOutputOctets = '%{Acct-Output-Octets}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress= '%{NAS-IP- Address}'" sql: accounting_update_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay) values('%{Acct- Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay- Time:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station- Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed- Protocol}', '%{Framed-IP-Address}', '0')" sql: accounting_start_query = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct- Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{Acct-Delay-Time}', '0')" sql: accounting_start_query_alt = "UPDATE radacct SET AcctStartTime = '%S', AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct- Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'" sql: accounting_stop_query = "UPDATE radacct SET AcctStopTime = '%S', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay = '%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User- Name}' AND NASIPAddress = '%{NAS-IP-Address}'" sql: accounting_stop_query_alt = "INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL- User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS- Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station- Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed- Protocol}', '%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')" sql: group_membership_query = "SELECT GroupName FROM usergroup WHERE UserName='%{SQL-User-Name}'" sql: connect_failure_retry_delay = 60 sql: simul_count_query = "" sql: simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE UserName='%{SQL- User-Name}' AND AcctStopTime = 0" sql: postauth_table = "radpostauth" sql: postauth_query = "INSERT into radpostauth (id, user, pass, reply, date) values ('', '%{User-Name}', '%{User-Password:-Chap- Password}', '%{reply:Packet-Type}', NOW())" sql: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.- _: /" rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked rlm_sql (sql): Attempting to connect to root@localhost:/radius rlm_sql (sql): starting 0 rlm_sql (sql): Attempting to connect rlm_sql_mysql #0 rlm_sql_mysql: Starting connect to MySQL server for #0 rlm_sql (sql): Connected new DB handle, #0 rlm_sql (sql): starting 1 rlm_sql (sql): Attempting to connect rlm_sql_mysql #1 rlm_sql_mysql: Starting connect to MySQL server for #1 rlm_sql (sql): Connected new DB handle, #1 rlm_sql (sql): starting 2 rlm_sql (sql): Attempting to connect rlm_sql_mysql #2 rlm_sql_mysql: Starting connect to MySQL server for #2 rlm_sql (sql): Connected new DB handle, #2 rlm_sql (sql): starting 3 rlm_sql (sql): Attempting to connect rlm_sql_mysql #3 rlm_sql_mysql: Starting connect to MySQL server for #3 rlm_sql (sql): Connected new DB handle, #3 rlm_sql (sql): starting 4 rlm_sql (sql): Attempting to connect rlm_sql_mysql #4 rlm_sql_mysql: Starting connect to MySQL server for #4 rlm_sql (sql): Connected new DB handle, #4 Module: Instantiated sql (sql) Module: Loaded SQL Counter sqlcounter: counter-name = "Daily-Session-Time" sqlcounter: check-name = "Max-Daily-Session" sqlcounter: key = "User-Name" sqlcounter: sqlmod-inst = "sql" sqlcounter: query = "SELECT SUM(AcctSessionTime - GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='%{%k}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'" sqlcounter: reset = "daily" sqlcounter: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.- _: /" rlm_sqlcounter: Counter attribute Daily-Session-Time is number 1830 rlm_sqlcounter: Check attribute Max-Daily-Session is number 1831 rlm_sqlcounter: Current Time: 1140529038 [2006-02-21 10:37:18], Next reset 1140577200 [2006-02-22 00:00:00] rlm_sqlcounter: Current Time: 1140529038 [2006-02-21 10:37:18], Prev reset 1140490800 [2006-02-21 00:00:00] Module: Instantiated sqlcounter (dailycounter) sqlcounter: counter-name = "Monthly-Session-Time" sqlcounter: check-name = "Max-Monthly-Session" sqlcounter: key = "User-Name" sqlcounter: sqlmod-inst = "sql" sqlcounter: query = "SELECT SUM(AcctSessionTime - GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='%{%k}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'" sqlcounter: reset = "monthly" sqlcounter: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.- _: /" rlm_sqlcounter: Counter attribute Monthly-Session-Time is number 1832 rlm_sqlcounter: Check attribute Max-Monthly-Session is number 1833 rlm_sqlcounter: Current Time: 1140529038 [2006-02-21 10:37:18], Next reset 1141182000 [2006-03-01 00:00:00] rlm_sqlcounter: Current Time: 1140529038 [2006-02-21 10:37:18], Prev reset 1138762800 [2006-02-01 00:00:00] Module: Instantiated sqlcounter (monthlycounter) Module: Loaded Acct-Unique-Session-Id acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Module: Instantiated acct_unique (acct_unique) Module: Loaded files files: usersfile = "/usr/local/etc/raddb/users" files: acctusersfile = "/usr/local/etc/raddb/acct_users" files: preproxy_usersfile = "/usr/local/etc/raddb/preproxy_users" files: compat = "no" Module: Instantiated files (files) detail: detailfile = "/var/log/radacct/%{Client-IP-Address}/detail- %Y%m%d" detail: detailperm = 384 detail: dirperm = 493 detail: locking = no Module: Instantiated detail (detail) Module: Loaded radutmp radutmp: filename = "/var/log/radutmp" radutmp: username = "%{User-Name}" radutmp: case_sensitive = yes radutmp: check_with_nas = yes radutmp: perm = 384 radutmp: callerid = yes Module: Instantiated radutmp (radutmp) Listening on authentication YYY.YYY.YYY.YYY:1812 Listening on accounting YYY.YYY.YYY.YYY:1813 Ready to process requests. rad_recv: Access-Request packet from host XXX.XXX.XXX.XXX:32770, id=0, length=216 User-Name = "test0001" CHAP-Challenge = 0xbb9b786a9857418d627cec741434bf5a CHAP-Password = 0x00e71611e921e4fd929f9bcdd5aeff2172 NAS-IP-Address = 0.0.0.0 Service-Type = Login-User Framed-IP-Address = 192.168.182.3 Calling-Station-Id = "00-04-23-63-0F-A7" Called-Station-Id = "00-13-46-70-3E-CF" NAS-Identifier = "mynas" Acct-Session-Id = "43fb0eac00000000" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 Message-Authenticator = 0xda8261dfb84b5ea5f4ff88c67780d76d WISPr-Logoff-URL = "http://192.168.182.1:3990/logoff" Processing the authorize section of radiusd.conf modcall: entering group authorize for request 0 modcall[authorize]: module "preprocess" returns ok for request 0 radius_xlat: '/var/log/radacct/XXX.XXX.XXX.XXX/auth-detail- 20060221' rlm_detail: /var/log/radacct/%{Client-IP-Address}/auth-detail- %Y%m%d expands to /var/log/radacct/XXX.XXX.XXX.XXX/auth-detail- 20060221 modcall[authorize]: module "auth_log" returns ok for request 0 rlm_chap: Setting 'Auth-Type := CHAP' modcall[authorize]: module "chap" returns ok for request 0 modcall[authorize]: module "mschap" returns noop for request 0 rlm_realm: No '@' in User-Name = "test0001", looking up realm NULL rlm_realm: No such realm "NULL" modcall[authorize]: module "suffix" returns noop for request 0 radius_xlat: 'test0001' rlm_sql (sql): sql_set_user escaped user --> 'test0001' radius_xlat: 'SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = 'test0001' ORDER BY id' rlm_sql (sql): Reserving sql socket id: 4 rlm_sql_mysql: query: SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = 'test0001' ORDER BY id radius_xlat: 'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,rad groupcheck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'test0001' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id' rlm_sql_mysql: query: SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,rad groupcheck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'test0001' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id radius_xlat: 'SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = 'test0001' ORDER BY id' rlm_sql_mysql: query: SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = 'test0001' ORDER BY id radius_xlat: 'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,rad groupreply.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'test0001' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id' rlm_sql_mysql: query: SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,rad groupreply.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'test0001' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id rlm_sql (sql): Released sql socket id: 4 modcall[authorize]: module "sql" returns ok for request 0 rlm_sqlcounter: Entering module authorize code sqlcounter_expand: 'SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'' radius_xlat: 'SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'' sqlcounter_expand: '%{sql:SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'}' radius_xlat: Running registered xlat function of module sql for string 'SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'' rlm_sql (sql): - sql_xlat radius_xlat: 'test0001' rlm_sql (sql): sql_set_user escaped user --> 'test0001' radius_xlat: 'SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'' radius_xlat: '/var/log/sqltrace.sql' rlm_sql (sql): Reserving sql socket id: 3 rlm_sql_mysql: query: SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800' rlm_sql (sql): row[0] returned NULL rlm_sql (sql): Released sql socket id: 3 radius_xlat: '' rlm_sqlcounter: (Check item - counter) is greater than zero rlm_sqlcounter: Authorized user test0001, check_item=54000, counter=0 rlm_sqlcounter: Sent Reply-Item for user test0001, Type=Session- Timeout, value=102112 modcall[authorize]: module "dailycounter" returns ok for request 0 rlm_sqlcounter: Entering module authorize code sqlcounter_expand: 'SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'' radius_xlat: 'SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'' sqlcounter_expand: '%{sql:SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'}' radius_xlat: Running registered xlat function of module sql for string 'SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'' rlm_sql (sql): - sql_xlat radius_xlat: 'test0001' rlm_sql (sql): sql_set_user escaped user --> 'test0001' radius_xlat: 'SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'' radius_xlat: '/var/log/sqltrace.sql' rlm_sql (sql): Reserving sql socket id: 2 rlm_sql_mysql: query: SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800' rlm_sql (sql): row[0] returned NULL rlm_sql (sql): Released sql socket id: 2 radius_xlat: '' rlm_sqlcounter: (Check item - counter) is greater than zero rlm_sqlcounter: Authorized user test0001, check_item=54000, counter=0 rlm_sqlcounter: Sent Reply-Item for user test0001, Type=Session- Timeout, value=54000 modcall[authorize]: module "monthlycounter" returns ok for request 0 modcall: leaving group authorize (returns ok) for request 0 rad_check_password: Found Auth-Type Local auth: type Local auth: user supplied CHAP-Password matches local User-Password Login OK: [test0001] (from client mynas port 0 cli 00-04-23-63-0F- A7) Processing the post-auth section of radiusd.conf modcall: entering group post-auth for request 0 rlm_sql (sql): Processing sql_postauth radius_xlat: 'test0001' rlm_sql (sql): sql_set_user escaped user --> 'test0001' radius_xlat: 'INSERT into radpostauth (id, user, pass, reply, date) values ('', 'test0001', 'Chap-Password', 'Access-Accept', NOW())' radius_xlat: '/var/log/sqltrace.sql' rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth (id, user, pass, reply, date) values ('', 'test0001', 'Chap- Password', 'Access-Accept', NOW()) rlm_sql (sql): Reserving sql socket id: 1 rlm_sql_mysql: query: INSERT into radpostauth (id, user, pass, reply, date) values ('', 'test0001', 'Chap-Password', 'Access- Accept', NOW()) rlm_sql (sql): Released sql socket id: 1 modcall[post-auth]: module "sql" returns ok for request 0 modcall: leaving group post-auth (returns ok) for request 0 Sending Access-Accept of id 0 to XXX.XXX.XXX.XXX port 32770 Session-Timeout = 54000 Finished request 0 Going to the next request --- Walking the entire request list --- Waking up in 6 seconds... rad_recv: Access-Request packet from host XXX.XXX.XXX.XXX:32770, id=0, length=216 Sending duplicate reply to client mynas:32770 - ID: 0 Re-sending Access-Accept of id 0 to XXX.XXX.XXX.XXX port 32770 --- Walking the entire request list --- Waking up in 4 seconds... rad_recv: Access-Request packet from host XXX.XXX.XXX.XXX:32770, id=0, length=216 Sending duplicate reply to client mynas:32770 - ID: 0 Re-sending Access-Accept of id 0 to XXX.XXX.XXX.XXX port 32770 --- Walking the entire request list --- Waking up in 3 seconds... rad_recv: Access-Request packet from host XXX.XXX.XXX.XXX:32770, id=0, length=216 Sending duplicate reply to client mynas:32770 - ID: 0 Re-sending Access-Accept of id 0 to XXX.XXX.XXX.XXX port 32770 --- Walking the entire request list --- Waking up in 1 seconds... --- Walking the entire request list --- Cleaning up request 0 ID 0 with timestamp 43fb17c0 Nothing to do. Sleeping until we see a request. rad_recv: Access-Request packet from host XXX.XXX.XXX.XXX:32770, id=0, length=216 User-Name = "test0001" CHAP-Challenge = 0xbb9b786a9857418d627cec741434bf5a CHAP-Password = 0x00e71611e921e4fd929f9bcdd5aeff2172 NAS-IP-Address = 0.0.0.0 Service-Type = Login-User Framed-IP-Address = 192.168.182.3 Calling-Station-Id = "00-04-23-63-0F-A7" Called-Station-Id = "00-13-46-70-3E-CF" NAS-Identifier = "mynas" Acct-Session-Id = "43fb0eac00000000" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 Message-Authenticator = 0xda8261dfb84b5ea5f4ff88c67780d76d WISPr-Logoff-URL = "http://192.168.182.1:3990/logoff" Processing the authorize section of radiusd.conf modcall: entering group authorize for request 1 modcall[authorize]: module "preprocess" returns ok for request 1 radius_xlat: '/var/log/radacct/XXX.XXX.XXX.XXX/auth-detail- 20060221' rlm_detail: /var/log/radacct/%{Client-IP-Address}/auth-detail- %Y%m%d expands to /var/log/radacct/XXX.XXX.XXX.XXX/auth-detail- 20060221 modcall[authorize]: module "auth_log" returns ok for request 1 rlm_chap: Setting 'Auth-Type := CHAP' modcall[authorize]: module "chap" returns ok for request 1 modcall[authorize]: module "mschap" returns noop for request 1 rlm_realm: No '@' in User-Name = "test0001", looking up realm NULL rlm_realm: No such realm "NULL" modcall[authorize]: module "suffix" returns noop for request 1 radius_xlat: 'test0001' rlm_sql (sql): sql_set_user escaped user --> 'test0001' radius_xlat: 'SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = 'test0001' ORDER BY id' rlm_sql (sql): Reserving sql socket id: 0 rlm_sql_mysql: query: SELECT id, UserName, Attribute, Value, op FROM radcheck WHERE Username = 'test0001' ORDER BY id radius_xlat: 'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,rad groupcheck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'test0001' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id' rlm_sql_mysql: query: SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,rad groupcheck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE usergroup.Username = 'test0001' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id radius_xlat: 'SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = 'test0001' ORDER BY id' rlm_sql_mysql: query: SELECT id, UserName, Attribute, Value, op FROM radreply WHERE Username = 'test0001' ORDER BY id radius_xlat: 'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,rad groupreply.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'test0001' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id' rlm_sql_mysql: query: SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,rad groupreply.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE usergroup.Username = 'test0001' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id rlm_sql (sql): Released sql socket id: 0 modcall[authorize]: module "sql" returns ok for request 1 rlm_sqlcounter: Entering module authorize code sqlcounter_expand: 'SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'' radius_xlat: 'SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'' sqlcounter_expand: '%{sql:SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'}' radius_xlat: Running registered xlat function of module sql for string 'SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'' rlm_sql (sql): - sql_xlat radius_xlat: 'test0001' rlm_sql (sql): sql_set_user escaped user --> 'test0001' radius_xlat: 'SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800'' radius_xlat: '/var/log/sqltrace.sql' rlm_sql (sql): Reserving sql socket id: 4 rlm_sql_mysql: query: SELECT SUM(AcctSessionTime - GREATEST((1140490800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1140490800' rlm_sql (sql): row[0] returned NULL rlm_sql (sql): Released sql socket id: 4 radius_xlat: '' rlm_sqlcounter: (Check item - counter) is greater than zero rlm_sqlcounter: Authorized user test0001, check_item=54000, counter=0 rlm_sqlcounter: Sent Reply-Item for user test0001, Type=Session- Timeout, value=102106 modcall[authorize]: module "dailycounter" returns ok for request 1 rlm_sqlcounter: Entering module authorize code sqlcounter_expand: 'SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'' radius_xlat: 'SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'' sqlcounter_expand: '%{sql:SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'}' radius_xlat: Running registered xlat function of module sql for string 'SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'' rlm_sql (sql): - sql_xlat radius_xlat: 'test0001' rlm_sql (sql): sql_set_user escaped user --> 'test0001' radius_xlat: 'SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800'' radius_xlat: '/var/log/sqltrace.sql' rlm_sql (sql): Reserving sql socket id: 3 rlm_sql_mysql: query: SELECT SUM(AcctSessionTime - GREATEST((1138762800 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='test0001' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1138762800' rlm_sql (sql): row[0] returned NULL rlm_sql (sql): Released sql socket id: 3 radius_xlat: '' rlm_sqlcounter: (Check item - counter) is greater than zero rlm_sqlcounter: Authorized user test0001, check_item=54000, counter=0 rlm_sqlcounter: Sent Reply-Item for user test0001, Type=Session- Timeout, value=54000 modcall[authorize]: module "monthlycounter" returns ok for request 1 modcall: leaving group authorize (returns ok) for request 1 rad_check_password: Found Auth-Type Local auth: type Local auth: user supplied CHAP-Password matches local User-Password Login OK: [test0001] (from client mynas port 0 cli 00-04-23-63-0F- A7) Processing the post-auth section of radiusd.conf modcall: entering group post-auth for request 1 rlm_sql (sql): Processing sql_postauth radius_xlat: 'test0001' rlm_sql (sql): sql_set_user escaped user --> 'test0001' radius_xlat: 'INSERT into radpostauth (id, user, pass, reply, date) values ('', 'test0001', 'Chap-Password', 'Access-Accept', NOW())' radius_xlat: '/var/log/sqltrace.sql' rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth (id, user, pass, reply, date) values ('', 'test0001', 'Chap- Password', 'Access-Accept', NOW()) rlm_sql (sql): Reserving sql socket id: 2 rlm_sql_mysql: query: INSERT into radpostauth (id, user, pass, reply, date) values ('', 'test0001', 'Chap-Password', 'Access- Accept', NOW()) rlm_sql (sql): Released sql socket id: 2 modcall[post-auth]: module "sql" returns ok for request 1 modcall: leaving group post-auth (returns ok) for request 1 Sending Access-Accept of id 0 to XXX.XXX.XXX.XXX port 32770 Session-Timeout = 54000 Finished request 1 Going to the next request --- Walking the entire request list --- Waking up in 6 seconds... rad_recv: Access-Request packet from host XXX.XXX.XXX.XXX:32770, id=0, length=216 Sending duplicate reply to client mynas:32770 - ID: 0 Re-sending Access-Accept of id 0 to XXX.XXX.XXX.XXX port 32770 --- Walking the entire request list --- Waking up in 4 seconds... rad_recv: Access-Request packet from host XXX.XXX.XXX.XXX:32770, id=0, length=216 Sending duplicate reply to client mynas:32770 - ID: 0 Re-sending Access-Accept of id 0 to XXX.XXX.XXX.XXX port 32770 --- Walking the entire request list --- Waking up in 3 seconds... --- Walking the entire request list --- Cleaning up request 1 ID 0 with timestamp 43fb17c6 Nothing to do. Sleeping until we see a request. .................................................. Entries in radius DB: mysql> SELECT * FROM radcheck; +-----+----------+---------------------+----+-------+ | id | UserName | Attribute | op | Value | +-----+----------+---------------------+----+-------+ | 459 | test0001 | Password | == | 0001 | | 461 | test0001 | Max-Monthly-Session | := | 54000 | | 463 | test0001 | Max-Daily-Session | := | 54000 | +-----+----------+---------------------+----+-------+ 3 rows in set (0.00 sec) mysql> SELECT * FROM radpostauth; +----+----------+---------------+---------------+------------------- --+ | id | user | pass | reply | date | +----+----------+---------------+---------------+------------------- --+ | 35 | test0001 | Chap-Password | Access-Accept | 2006-02-21 10:12:12 | | 36 | test0001 | Chap-Password | Access-Accept | 2006-02-21 10:12:18 | +----+----------+---------------+---------------+------------------- --+ 2 rows in set (0.00 sec) mysql> SELECT * FROM usergroup; +-----+----------+-----------+ | id | UserName | GroupName | +-----+----------+-----------+ | 115 | test0001 | dynamic | +-----+----------+-----------+ 1 row in set (0.00 sec) ................................................... this is my radiusd.conf prefix = /usr/local exec_prefix = ${prefix} sysconfdir = ${prefix}/etc localstatedir = /var sbindir = ${exec_prefix}/sbin logdir = /var/log raddbdir = ${sysconfdir}/raddb radacctdir = ${logdir}/radacct confdir = ${raddbdir} run_dir = ${localstatedir}/run/radiusd log_file = ${logdir}/radius.log libdir = ${exec_prefix}/lib pidfile = ${run_dir}/radiusd.pid max_request_time = 30 delete_blocked_requests = no cleanup_delay = 5 max_requests = 1024 bind_address = YYY.YYY.YYY.YYY port = 0 hostname_lookups = no allow_core_dumps = no regular_expressions = yes extended_expressions = yes log_stripped_names = no log_auth = yes log_auth_badpass = no log_auth_goodpass = no usercollide = no lower_user = no lower_pass = no nospace_user = no nospace_pass = no checkrad = ${sbindir}/checkrad security { max_attributes = 200 reject_delay = 1 status_server = no } proxy_requests = yes $INCLUDE ${confdir}/proxy.conf $INCLUDE ${confdir}/clients.conf snmp = no $INCLUDE ${confdir}/snmp.conf thread pool { start_servers = 5 max_servers = 32 min_spare_servers = 3 max_spare_servers = 10 max_requests_per_server = 0 } modules { pap { encryption_scheme = crypt } chap { authtype = CHAP } pam { pam_auth = radiusd } unix { cache = no cache_reload = 600 radwtmp = ${logdir}/radwtmp } mschap { authtype = MS-CHAP } ldap { server = "ldap.your.domain" basedn = "o=My Org,c=UA" filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" start_tls = no access_attr = "dialupAccess" dictionary_mapping = ${raddbdir}/ldap.attrmap ldap_connections_number = 5 timeout = 4 timelimit = 3 net_timeout = 1 } realm IPASS { format = prefix delimiter = "/" ignore_default = no ignore_null = no } realm suffix { format = suffix delimiter = "@" ignore_default = no ignore_null = no } realm realmpercent { format = suffix delimiter = "%" ignore_default = no ignore_null = no } realm ntdomain { format = prefix delimiter = "\\" ignore_default = no ignore_null = no } checkval { item-name = Calling-Station-Id check-name = Calling-Station-Id data-type = string } preprocess { huntgroups = ${confdir}/huntgroups hints = ${confdir}/hints with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no } files { usersfile = ${confdir}/users acctusersfile = ${confdir}/acct_users preproxy_usersfile = ${confdir}/preproxy_users compat = no } detail { detailfile = ${radacctdir}/%{Client-IP-Address}/detail-%Y%m%d detailperm = 0600 } detail auth_log { detailfile = ${radacctdir}/%{Client-IP-Address}/auth-detail- %Y%m%d detailperm = 0600 } acct_unique { key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP- Address, NAS-Port" } $INCLUDE ${confdir}/sql.conf radutmp { filename = ${logdir}/radutmp username = %{User-Name} case_sensitive = yes check_with_nas = yes perm = 0600 callerid = "yes" } radutmp sradutmp { filename = ${logdir}/sradutmp perm = 0644 callerid = "no" } attr_filter { attrsfile = ${confdir}/attrs } counter daily { filename = ${raddbdir}/db.daily key = User-Name count-attribute = Acct-Session-Time reset = daily counter-name = Daily-Session-Time check-name = Max-Daily-Session allowed-servicetype = Framed-User cache-size = 5000 } sqlcounter dailycounter { counter-name = Daily-Session-Time check-name = Max-Daily-Session sqlmod-inst = sql key = User-Name reset = daily query = "SELECT SUM(AcctSessionTime - \ GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) \ FROM radacct WHERE UserName='%{%k}' AND \ UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'" } sqlcounter monthlycounter { counter-name = Monthly-Session-Time check-name = Max-Monthly-Session sqlmod-inst = sql key = User-Name reset = monthly query = "SELECT SUM(AcctSessionTime - \ GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) \ FROM radacct WHERE UserName='%{%k}' AND \ UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'" } always fail { rcode = fail } always reject { rcode = reject } always ok { rcode = ok simulcount = 0 mpp = no } expr { } digest { } exec { wait = yes input_pairs = request } exec echo { wait = yes program = "/bin/echo %{User-Name}" input_pairs = request output_pairs = reply } ippool main_pool { range-start = 192.168.1.1 range-stop = 192.168.3.254 netmask = 255.255.255.0 cache-size = 800 session-db = ${raddbdir}/db.ippool ip-index = ${raddbdir}/db.ipindex override = no maximum-timeout = 0 } } instantiate { expr } authorize { preprocess auth_log chap mschap suffix sql dailycounter monthlycounter } authenticate { Auth-Type PAP { pap } Auth-Type CHAP { chap } Auth-Type MS-CHAP { mschap } unix } preacct { preprocess acct_unique suffix files } accounting { detail unix radutmp sql } session { radutmp } post-auth { sql } pre-proxy { } post-proxy { } ............................................ Any help would be most appreciated. thanks! Bill Concerned about your privacy? Instantly send FREE secure email, no account required http://www.hushmail.com/send?l=480 Get the best prices on SSL certificates from Hushmail https://www.hushssl.com?l=485
<bdab@hushmail.com> wrote:
Basically I've got duplicate entries in radpostauth, no entries in radacct and the NAS does not recognize the successful authentication even though from the radius server point of view it seems to get authentication right.
Then either the reply is coming from an IP that the NAS doesn't like, or the shared secret is wrong. Once you get the NAS to accept the response from the server, the duplicate entries in will disappear, and accounting will start. I suggest using 'tcpdump' on the network to see what's going on with the RADIUS packets. Look at src/dst IP's... Alan DeKok.
participants (2)
-
Alan DeKok -
bdab@hushmail.com