Hi Alan, the following is a packet which is not recognizeing the expr value in rad_reply or rad_groupreply: radreply: 5 gunther Session-Timeout = `%{expr: 3600 - 400}` Should be 3200 seconds ... but results into 0 seconds.
---------------------------------------------------------------------- rad_recv: Access-Request packet from host 192.168.0.254:2055, id=0, length=227 User-Name = "gunther" CHAP-Challenge = 0x26222c6c476b3be21958dc1ddc0ad3db CHAP-Password = 0x00a4b8f5b9ba96eb52251722039e1091e2 NAS-IP-Address = 0.0.0.0 Service-Type = Login-User Framed-IP-Address = 192.168.182.4 Calling-Station-Id = "00-0D-93-88-5C-B9" Called-Station-Id = "00-13-10-94-A9-14" NAS-Identifier = "[EMAIL PROTECTED]" Acct-Session-Id = "4341d27f00000000" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 Message-Authenticator = 0x94c26b45aefa054e6ab79d4d6bc26562 WISPr-Logoff-URL = "http://192.168.182.1:3990/logoff" Tue Oct 4 00:53:46 2005 : Debug: Processing the authorize section of radiusd.conf Tue Oct 4 00:53:46 2005 : Debug: modcall: entering group authorize for request 1 Tue Oct 4 00:53:46 2005 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1 Tue Oct 4 00:53:46 2005 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1 Tue Oct 4 00:53:46 2005 : Debug: modcall[authorize]: module "preprocess" returns ok for request 1 Tue Oct 4 00:53:46 2005 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 1 Tue Oct 4 00:53:46 2005 : Debug: rlm_realm: No '@' in User-Name = "gunther", looking up realm NULL Tue Oct 4 00:53:46 2005 : Debug: rlm_realm: No such realm "NULL" Tue Oct 4 00:53:46 2005 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 1 Tue Oct 4 00:53:46 2005 : Debug: modcall[authorize]: module "suffix" returns noop for request 1 Tue Oct 4 00:53:46 2005 : Debug: modsingle[authorize]: calling sql (rlm_sql) for request 1 Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'gunther' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'gunther' Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'SELECT user_id,user_username,user_attribute,user_value,user_op FROM phs_user WHERE user_username = 'gunther' ORDER BY user_id' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 2 Tue Oct 4 00:53:46 2005 : Debug: rlm_sql_mysql: query: SELECT user_id,user_username,user_attribute,user_value,user_op FROM phs_user WHERE user_username = 'gunther' ORDER BY user_id Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'SELECT phs_radgroupcheck.radgroupcheck_id,phs_radgroupcheck.radgroupcheck_groupname ,phs_radgroupcheck.radgroupcheck_attribute,phs_radgroupcheck.radgroupcheck_v alue,phs_radgroupcheck.radgroupcheck_op FROM phs_radgroupcheck,phs_usergroup WHERE phs_usergroup.usergroup_username = 'gunther' AND phs_usergroup.usergroup_groupname = phs_radgroupcheck.radgroupcheck_groupname ORDER BY phs_radgroupcheck.radgroupcheck_id' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql_mysql: query: SELECT phs_radgroupcheck.radgroupcheck_id,phs_radgroupcheck.radgroupcheck_groupname ,phs_radgroupcheck.radgroupcheck_attribute,phs_radgroupcheck.radgroupcheck_v alue,phs_radgroupcheck.radgroupcheck_op FROM phs_radgroupcheck,phs_usergroup WHERE phs_usergroup.usergroup_username = 'gunther' AND phs_usergroup.usergroup_groupname = phs_radgroupcheck.radgroupcheck_groupname ORDER BY phs_radgroupcheck.radgroupcheck_id Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'SELECT radreply_id,radreply_username,radreply_attribute,radreply_value,radreply_op FROM phs_radreply WHERE radreply_username = 'gunther' ORDER BY radreply_id' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql_mysql: query: SELECT radreply_id,radreply_username,radreply_attribute,radreply_value,radreply_op FROM phs_radreply WHERE radreply_username = 'gunther' ORDER BY radreply_id Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'SELECT phs_radgroupreply.radgroupreply_id,phs_radgroupreply.radgroupreply_groupname ,phs_radgroupreply.radgroupreply_attribute,phs_radgroupreply.radgroupreply_v alue,phs_radgroupreply.radgroupreply_op FROM phs_radgroupreply,phs_usergroup WHERE phs_usergroup.usergroup_username = 'gunther' AND phs_usergroup.usergroup_groupname = phs_radgroupreply.radgroupreply_groupname ORDER BY phs_radgroupreply.radgroupreply_id' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql_mysql: query: SELECT phs_radgroupreply.radgroupreply_id,phs_radgroupreply.radgroupreply_groupname ,phs_radgroupreply.radgroupreply_attribute,phs_radgroupreply.radgroupreply_v alue,phs_radgroupreply.radgroupreply_op FROM phs_radgroupreply,phs_usergroup WHERE phs_usergroup.usergroup_username = 'gunther' AND phs_usergroup.usergroup_groupname = phs_radgroupreply.radgroupreply_groupname ORDER BY phs_radgroupreply.radgroupreply_id Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: '=' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): Released sql socket id: 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[authorize]: returned from sql (rlm_sql) for request 1 Tue Oct 4 00:53:46 2005 : Debug: modcall[authorize]: module "sql" returns ok for request 1 Tue Oct 4 00:53:46 2005 : Debug: modsingle[authorize]: calling files (rlm_files) for request 1 Tue Oct 4 00:53:46 2005 : Debug: users: Matched entry DEFAULT at line 230 Tue Oct 4 00:53:46 2005 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 1 Tue Oct 4 00:53:46 2005 : Debug: modcall[authorize]: module "files" returns ok for request 1 Tue Oct 4 00:53:46 2005 : Debug: modcall: group authorize returns ok for request 1 Tue Oct 4 00:53:46 2005 : Debug: auth: type Local Tue Oct 4 00:53:46 2005 : Debug: auth: user supplied CHAP-Password matches local User-Password Tue Oct 4 00:53:46 2005 : Debug: Processing the post-auth section of radiusd.conf Tue Oct 4 00:53:46 2005 : Debug: modcall: entering group post-auth for request 1 Tue Oct 4 00:53:46 2005 : Debug: modsingle[post-auth]: calling sql (rlm_sql) for request 1 Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): Processing sql_postauth Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'gunther' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'gunther' Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'INSERT into phs_radpostauth (radpostauth_id, radpostauth_user, radpostauth_pass, radpostauth_reply, radpostauth_mdate) values ('', 'gunther', 'Chap-Password', 'Access-Accept', NOW())' Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: '/var/log/radius/sqltrace.sql' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT into phs_radpostauth (radpostauth_id, radpostauth_user, radpostauth_pass, radpostauth_reply, radpostauth_mdate) values ('', 'gunther', 'Chap-Password', 'Access-Accept', NOW()) Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 1 Tue Oct 4 00:53:46 2005 : Debug: rlm_sql_mysql: query: INSERT into phs_radpostauth (radpostauth_id, radpostauth_user, radpostauth_pass, radpostauth_reply, radpostauth_mdate) values ('', 'gunther', 'Chap-Password', 'Access-Accept', NOW()) Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): Released sql socket id: 1 Tue Oct 4 00:53:46 2005 : Debug: modsingle[post-auth]: returned from sql (rlm_sql) for request 1 Tue Oct 4 00:53:46 2005 : Debug: modcall[post-auth]: module "sql" returns ok for request 1 Tue Oct 4 00:53:46 2005 : Debug: modcall: group post-auth returns ok for request 1 Sending Access-Accept of id 0 to 192.168.0.254:2055 Session-Timeout = 0 Tue Oct 4 00:53:46 2005 : Debug: Finished request 1 Tue Oct 4 00:53:46 2005 : Debug: Going to the next request Tue Oct 4 00:53:46 2005 : Debug: --- Walking the entire request list --- Tue Oct 4 00:53:46 2005 : Debug: Waking up in 6 seconds... rad_recv: Accounting-Request packet from host 192.168.0.254:2052, id=16, length=142 Acct-Status-Type = Start User-Name = "gunther" Calling-Station-Id = "00-0D-93-88-5C-B9" Called-Station-Id = "00-13-10-94-A9-14" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 NAS-Port-Id = "00000000" NAS-IP-Address = 0.0.0.0 NAS-Identifier = "[EMAIL PROTECTED]" Framed-IP-Address = 192.168.182.4 Acct-Session-Id = "4341d27f00000000" Tue Oct 4 00:53:46 2005 : Debug: Processing the preacct section of radiusd.conf Tue Oct 4 00:53:46 2005 : Debug: modcall: entering group preacct for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[preacct]: calling preprocess (rlm_preprocess) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[preacct]: returned from preprocess (rlm_preprocess) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall[preacct]: module "preprocess" returns noop for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[preacct]: calling acct_unique (rlm_acct_unique) for request 2 Tue Oct 4 00:53:46 2005 : Debug: rlm_acct_unique: Hashing 'NAS-Port = 0,Client-IP-Address = 192.168.0.254,NAS-IP-Address = 0.0.0.0,Acct-Session-Id = "4341d27f00000000",User-Name = "gunther"' Tue Oct 4 00:53:46 2005 : Debug: rlm_acct_unique: Acct-Unique-Session-ID = "a110560f3fb91d82". Tue Oct 4 00:53:46 2005 : Debug: modsingle[preacct]: returned from acct_unique (rlm_acct_unique) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall[preacct]: module "acct_unique" returns ok for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[preacct]: calling suffix (rlm_realm) for request 2 Tue Oct 4 00:53:46 2005 : Debug: rlm_realm: No '@' in User-Name = "gunther", looking up realm NULL Tue Oct 4 00:53:46 2005 : Debug: rlm_realm: No such realm "NULL" Tue Oct 4 00:53:46 2005 : Debug: modsingle[preacct]: returned from suffix (rlm_realm) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall[preacct]: module "suffix" returns noop for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[preacct]: calling files (rlm_files) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[preacct]: returned from files (rlm_files) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall[preacct]: module "files" returns noop for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall: group preacct returns ok for request 2 Tue Oct 4 00:53:46 2005 : Debug: Processing the accounting section of radiusd.conf Tue Oct 4 00:53:46 2005 : Debug: modcall: entering group accounting for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[accounting]: calling detail (rlm_detail) for request 2 Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: '/var/log/radius/radacct/192.168.0.254/detail-20051004' Tue Oct 4 00:53:46 2005 : Debug: rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/radius/radacct/192.168.0.254/detail-20051004 Tue Oct 4 00:53:46 2005 : Debug: modsingle[accounting]: returned from detail (rlm_detail) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall[accounting]: module "detail" returns ok for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[accounting]: calling unix (rlm_unix) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[accounting]: returned from unix (rlm_unix) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall[accounting]: module "unix" returns ok for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[accounting]: calling sql (rlm_sql) for request 2 Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'gunther' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> 'gunther' Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'INSERT into phs_radacct (radacct_session_id, radacct_unique_id, radacct_username, radacct_realm, radacct_nas_ipaddress, radacct_nas_portid, radacct_nas_porttype, radacct_starttime, radacct_stoptime, radacct_sessiontime, radacct_authentic, radacct_connectinfo_start, radacct_connectinfo_stop, radacct_inputoctets, radacct_outputoctets, radacct_called_stationId, radacct_calling_stationId, radacct_terminatecause, radacct_servicetype, radacct_framedprotocol, radacct_framedipaddress, radacct_startdelay, radacct_stopdelay) values('4341d27f00000000', 'a110560f3fb91d82', 'gunther', '', '0.0.0.0', '0', 'Wireless-802.11', '2005-10-04 00:53:46', '0', '0', '', '', '', '0', '0', '00-13-10-94-A9-14', '00-0D-93-88-5C-B9', '', '', '', '192.168.182.4', '', '0')' Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: '/var/log/radius/sqltrace.sql' Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 0 Tue Oct 4 00:53:46 2005 : Debug: rlm_sql_mysql: query: INSERT into phs_radacct (radacct_session_id, radacct_unique_id, radacct_username, radacct_realm, radacct_nas_ipaddress, radacct_nas_portid, radacct_nas_porttype, radacct_starttime, radacct_stoptime, radacct_sessiontime, radacct_authentic, radacct_connectinfo_start, radacct_connectinfo_stop, radacct_inputoctets, radacct_outputoctets, radacct_called_stationId, radacct_calling_stationId, radacct_terminatecause, radacct_servicetype, radacct_framedprotocol, radacct_framedipaddress, radacct_startdelay, radacct_stopdelay) values('4341d27f00000000', 'a110560f3fb91d82', 'gunther', '', '0.0.0.0', '0', 'Wireless-802.11', '2005-10-04 00:53:46', '0', '0', '', '', '', '0', '0', '00-13-10-94-A9-14', '00-0D-93-88-5C-B9', '', '', '', '192.168.182.4', '', '0') Tue Oct 4 00:53:46 2005 : Debug: rlm_sql (sql): Released sql socket id: 0 Tue Oct 4 00:53:46 2005 : Debug: modsingle[accounting]: returned from sql (rlm_sql) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall[accounting]: module "sql" returns ok for request 2 Tue Oct 4 00:53:46 2005 : Debug: modsingle[accounting]: calling radutmp (rlm_radutmp) for request 2 Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: '/var/log/radius/radutmp' Tue Oct 4 00:53:46 2005 : Debug: radius_xlat: 'gunther' Tue Oct 4 00:53:46 2005 : Debug: modsingle[accounting]: returned from radutmp (rlm_radutmp) for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall[accounting]: module "radutmp" returns ok for request 2 Tue Oct 4 00:53:46 2005 : Debug: modcall: group accounting returns ok for request 2 Sending Accounting-Response of id 16 to 192.168.0.254:2052 Tue Oct 4 00:53:46 2005 : Debug: Finished request 2 Tue Oct 4 00:53:46 2005 : Debug: Going to the next request Tue Oct 4 00:53:46 2005 : Debug: Cleaning up request 2 ID 16 with timestamp 43420ada Tue Oct 4 00:53:46 2005 : Debug: rl_next: returning NULL Tue Oct 4 00:53:46 2005 : Debug: Waking up in 6 seconds... Tue Oct 4 00:53:52 2005 : Debug: --- Walking the entire request list --- Tue Oct 4 00:53:52 2005 : Debug: Cleaning up request 1 ID 0 with timestamp 43420ada Tue Oct 4 00:53:52 2005 : Debug: Nothing to do. Sleeping until we see a request. ----------------------------------------------------------------------- the following is a packet which is recognizeing the expr value in users: ----------------------------------------------------------------------- With rad_recv: Access-Request packet from host 192.168.0.254:2055, id=0, length=232 User-Name = "[EMAIL PROTECTED]" CHAP-Challenge = 0xfa6f5a59e681faf6aff8b157b4b61769 CHAP-Password = 0x00084243d775255b864dff914e7be8687d NAS-IP-Address = 0.0.0.0 Service-Type = Login-User Framed-IP-Address = 192.168.182.4 Calling-Station-Id = "00-0D-93-88-5C-B9" Called-Station-Id = "00-13-10-94-A9-14" NAS-Identifier = "[EMAIL PROTECTED]" Acct-Session-Id = "4341d40e00000000" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 Message-Authenticator = 0xa941bb6f6ad3c4ece1e0a70ef77fcd77 WISPr-Logoff-URL = "http://192.168.182.1:3990/logoff" Tue Oct 4 01:00:33 2005 : Debug: Processing the authorize section of radiusd.conf Tue Oct 4 01:00:33 2005 : Debug: modcall: entering group authorize for request 1 Tue Oct 4 01:00:33 2005 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1 Tue Oct 4 01:00:33 2005 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1 Tue Oct 4 01:00:33 2005 : Debug: modcall[authorize]: module "preprocess" returns ok for request 1 Tue Oct 4 01:00:33 2005 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 1 Tue Oct 4 01:00:33 2005 : Debug: rlm_realm: Looking up realm "norm" for User-Name = "[EMAIL PROTECTED]" Tue Oct 4 01:00:33 2005 : Debug: rlm_realm: No such realm "norm" Tue Oct 4 01:00:33 2005 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 1 Tue Oct 4 01:00:33 2005 : Debug: modcall[authorize]: module "suffix" returns noop for request 1 Tue Oct 4 01:00:33 2005 : Debug: modsingle[authorize]: calling sql (rlm_sql) for request 1 Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> '[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: 'SELECT user_id,user_username,user_attribute,user_value,user_op FROM phs_user WHERE user_username = '[EMAIL PROTECTED]' ORDER BY user_id' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 2 Tue Oct 4 01:00:33 2005 : Debug: rlm_sql_mysql: query: SELECT user_id,user_username,user_attribute,user_value,user_op FROM phs_user WHERE user_username = '[EMAIL PROTECTED]' ORDER BY user_id Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: 'SELECT phs_radgroupcheck.radgroupcheck_id,phs_radgroupcheck.radgroupcheck_groupname ,phs_radgroupcheck.radgroupcheck_attribute,phs_radgroupcheck.radgroupcheck_v alue,phs_radgroupcheck.radgroupcheck_op FROM phs_radgroupcheck,phs_usergroup WHERE phs_usergroup.usergroup_username = '[EMAIL PROTECTED]' AND phs_usergroup.usergroup_groupname = phs_radgroupcheck.radgroupcheck_groupname ORDER BY phs_radgroupcheck.radgroupcheck_id' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql_mysql: query: SELECT phs_radgroupcheck.radgroupcheck_id,phs_radgroupcheck.radgroupcheck_groupname ,phs_radgroupcheck.radgroupcheck_attribute,phs_radgroupcheck.radgroupcheck_v alue,phs_radgroupcheck.radgroupcheck_op FROM phs_radgroupcheck,phs_usergroup WHERE phs_usergroup.usergroup_username = '[EMAIL PROTECTED]' AND phs_usergroup.usergroup_groupname = phs_radgroupcheck.radgroupcheck_groupname ORDER BY phs_radgroupcheck.radgroupcheck_id Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: 'SELECT radreply_id,radreply_username,radreply_attribute,radreply_value,radreply_op FROM phs_radreply WHERE radreply_username = '[EMAIL PROTECTED]' ORDER BY radreply_id' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql_mysql: query: SELECT radreply_id,radreply_username,radreply_attribute,radreply_value,radreply_op FROM phs_radreply WHERE radreply_username = '[EMAIL PROTECTED]' ORDER BY radreply_id Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: 'SELECT phs_radgroupreply.radgroupreply_id,phs_radgroupreply.radgroupreply_groupname ,phs_radgroupreply.radgroupreply_attribute,phs_radgroupreply.radgroupreply_v alue,phs_radgroupreply.radgroupreply_op FROM phs_radgroupreply,phs_usergroup WHERE phs_usergroup.usergroup_username = '[EMAIL PROTECTED]' AND phs_usergroup.usergroup_groupname = phs_radgroupreply.radgroupreply_groupname ORDER BY phs_radgroupreply.radgroupreply_id' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql_mysql: query: SELECT phs_radgroupreply.radgroupreply_id,phs_radgroupreply.radgroupreply_groupname ,phs_radgroupreply.radgroupreply_attribute,phs_radgroupreply.radgroupreply_v alue,phs_radgroupreply.radgroupreply_op FROM phs_radgroupreply,phs_usergroup WHERE phs_usergroup.usergroup_username = '[EMAIL PROTECTED]' AND phs_usergroup.usergroup_groupname = phs_radgroupreply.radgroupreply_groupname ORDER BY phs_radgroupreply.radgroupreply_id Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): Released sql socket id: 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[authorize]: returned from sql (rlm_sql) for request 1 Tue Oct 4 01:00:33 2005 : Debug: modcall[authorize]: module "sql" returns ok for request 1 Tue Oct 4 01:00:33 2005 : Debug: modsingle[authorize]: calling files (rlm_files) for request 1 Tue Oct 4 01:00:33 2005 : Debug: users: Matched entry DEFAULT at line 230 Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: Running registered xlat function of module expr for string ' %{sql:SELECT IF(NOW() <= user_stoptime, TIME_TO_SEC(TIMEDIFF(user_stoptime, IF(NOW() >= user_starttime, now(), DATE_SUB(user_stoptime, INTERVAL 1 SECOND)))), 1) FROM phs_user WHERE user_username='%{User-Name}'}' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: Running registered xlat function of module sql for string 'SELECT IF(NOW() <= user_stoptime, TIME_TO_SEC(TIMEDIFF(user_stoptime, IF(NOW() >= user_starttime, now(), DATE_SUB(user_stoptime, INTERVAL 1 SECOND)))), 1) FROM phs_user WHERE user_username='%{User-Name}'' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): - sql_xlat Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> '[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: 'SELECT IF(NOW() <= user_stoptime, TIME_TO_SEC(TIMEDIFF(user_stoptime, IF(NOW() >= user_starttime, now(), DATE_SUB(user_stoptime, INTERVAL 1 SECOND)))), 1) FROM phs_user WHERE user_username='[EMAIL PROTECTED]'' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '/var/log/radius/sqltrace.sql' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 1 Tue Oct 4 01:00:33 2005 : Debug: rlm_sql_mysql: query: SELECT IF(NOW() <= user_stoptime, TIME_TO_SEC(TIMEDIFF(user_stoptime, IF(NOW() >= user_starttime, now(), DATE_SUB(user_stoptime, INTERVAL 1 SECOND)))), 1) FROM phs_user WHERE user_username='[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): - sql_xlat finished Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): Released sql socket id: 1 Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: ' 601167' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '601167' Tue Oct 4 01:00:33 2005 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 1 Tue Oct 4 01:00:33 2005 : Debug: modcall[authorize]: module "files" returns ok for request 1 Tue Oct 4 01:00:33 2005 : Debug: modcall: group authorize returns ok for request 1 Tue Oct 4 01:00:33 2005 : Debug: auth: type Local Tue Oct 4 01:00:33 2005 : Debug: auth: user supplied CHAP-Password matches local User-Password Tue Oct 4 01:00:33 2005 : Debug: Processing the post-auth section of radiusd.conf Tue Oct 4 01:00:33 2005 : Debug: modcall: entering group post-auth for request 1 Tue Oct 4 01:00:33 2005 : Debug: modsingle[post-auth]: calling sql (rlm_sql) for request 1 Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): Processing sql_postauth Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> '[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: 'INSERT into phs_radpostauth (radpostauth_id, radpostauth_user, radpostauth_pass, radpostauth_reply, radpostauth_mdate) values ('', '[EMAIL PROTECTED]', 'Chap-Password', 'Access-Accept', NOW())' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '/var/log/radius/sqltrace.sql' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT into phs_radpostauth (radpostauth_id, radpostauth_user, radpostauth_pass, radpostauth_reply, radpostauth_mdate) values ('', '[EMAIL PROTECTED]', 'Chap-Password', 'Access-Accept', NOW()) Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 0 Tue Oct 4 01:00:33 2005 : Debug: rlm_sql_mysql: query: INSERT into phs_radpostauth (radpostauth_id, radpostauth_user, radpostauth_pass, radpostauth_reply, radpostauth_mdate) values ('', '[EMAIL PROTECTED]', 'Chap-Password', 'Access-Accept', NOW()) Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): Released sql socket id: 0 Tue Oct 4 01:00:33 2005 : Debug: modsingle[post-auth]: returned from sql (rlm_sql) for request 1 Tue Oct 4 01:00:33 2005 : Debug: modcall[post-auth]: module "sql" returns ok for request 1 Tue Oct 4 01:00:33 2005 : Debug: modcall: group post-auth returns ok for request 1 Sending Access-Accept of id 0 to 192.168.0.254:2055 Session-Timeout = 601167 Tue Oct 4 01:00:33 2005 : Debug: Finished request 1 Tue Oct 4 01:00:33 2005 : Debug: Going to the next request Tue Oct 4 01:00:33 2005 : Debug: --- Walking the entire request list --- Tue Oct 4 01:00:33 2005 : Debug: Waking up in 6 seconds... rad_recv: Accounting-Request packet from host 192.168.0.254:2052, id=18, length=147 Acct-Status-Type = Start User-Name = "[EMAIL PROTECTED]" Calling-Station-Id = "00-0D-93-88-5C-B9" Called-Station-Id = "00-13-10-94-A9-14" NAS-Port-Type = Wireless-802.11 NAS-Port = 0 NAS-Port-Id = "00000000" NAS-IP-Address = 0.0.0.0 NAS-Identifier = "[EMAIL PROTECTED]" Framed-IP-Address = 192.168.182.4 Acct-Session-Id = "4341d40e00000000" Tue Oct 4 01:00:33 2005 : Debug: Processing the preacct section of radiusd.conf Tue Oct 4 01:00:33 2005 : Debug: modcall: entering group preacct for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[preacct]: calling preprocess (rlm_preprocess) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[preacct]: returned from preprocess (rlm_preprocess) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall[preacct]: module "preprocess" returns noop for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[preacct]: calling acct_unique (rlm_acct_unique) for request 2 Tue Oct 4 01:00:33 2005 : Debug: rlm_acct_unique: Hashing 'NAS-Port = 0,Client-IP-Address = 192.168.0.254,NAS-IP-Address = 0.0.0.0,Acct-Session-Id = "4341d40e00000000",User-Name = "[EMAIL PROTECTED]"' Tue Oct 4 01:00:33 2005 : Debug: rlm_acct_unique: Acct-Unique-Session-ID = "690cc01eacab085e". Tue Oct 4 01:00:33 2005 : Debug: modsingle[preacct]: returned from acct_unique (rlm_acct_unique) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall[preacct]: module "acct_unique" returns ok for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[preacct]: calling suffix (rlm_realm) for request 2 Tue Oct 4 01:00:33 2005 : Debug: rlm_realm: Looking up realm "norm" for User-Name = "[EMAIL PROTECTED]" Tue Oct 4 01:00:33 2005 : Debug: rlm_realm: No such realm "norm" Tue Oct 4 01:00:33 2005 : Debug: modsingle[preacct]: returned from suffix (rlm_realm) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall[preacct]: module "suffix" returns noop for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[preacct]: calling files (rlm_files) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[preacct]: returned from files (rlm_files) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall[preacct]: module "files" returns noop for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall: group preacct returns ok for request 2 Tue Oct 4 01:00:33 2005 : Debug: Processing the accounting section of radiusd.conf Tue Oct 4 01:00:33 2005 : Debug: modcall: entering group accounting for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[accounting]: calling detail (rlm_detail) for request 2 Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '/var/log/radius/radacct/192.168.0.254/detail-20051004' Tue Oct 4 01:00:33 2005 : Debug: rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/radius/radacct/192.168.0.254/detail-20051004 Tue Oct 4 01:00:33 2005 : Debug: modsingle[accounting]: returned from detail (rlm_detail) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall[accounting]: module "detail" returns ok for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[accounting]: calling unix (rlm_unix) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[accounting]: returned from unix (rlm_unix) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall[accounting]: module "unix" returns ok for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[accounting]: calling sql (rlm_sql) for request 2 Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): sql_set_user escaped user --> '[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: 'INSERT into phs_radacct (radacct_session_id, radacct_unique_id, radacct_username, radacct_realm, radacct_nas_ipaddress, radacct_nas_portid, radacct_nas_porttype, radacct_starttime, radacct_stoptime, radacct_sessiontime, radacct_authentic, radacct_connectinfo_start, radacct_connectinfo_stop, radacct_inputoctets, radacct_outputoctets, radacct_called_stationId, radacct_calling_stationId, radacct_terminatecause, radacct_servicetype, radacct_framedprotocol, radacct_framedipaddress, radacct_startdelay, radacct_stopdelay) values('4341d40e00000000', '690cc01eacab085e', '[EMAIL PROTECTED]', '', '0.0.0.0', '0', 'Wireless-802.11', '2005-10-04 01:00:33', '0', '0', '', '', '', '0', '0', '00-13-10-94-A9-14', '00-0D-93-88-5C-B9', '', '', '', '192.168.182.4', '', '0')' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '/var/log/radius/sqltrace.sql' Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 4 Tue Oct 4 01:00:33 2005 : Debug: rlm_sql_mysql: query: INSERT into phs_radacct (radacct_session_id, radacct_unique_id, radacct_username, radacct_realm, radacct_nas_ipaddress, radacct_nas_portid, radacct_nas_porttype, radacct_starttime, radacct_stoptime, radacct_sessiontime, radacct_authentic, radacct_connectinfo_start, radacct_connectinfo_stop, radacct_inputoctets, radacct_outputoctets, radacct_called_stationId, radacct_calling_stationId, radacct_terminatecause, radacct_servicetype, radacct_framedprotocol, radacct_framedipaddress, radacct_startdelay, radacct_stopdelay) values('4341d40e00000000', '690cc01eacab085e', '[EMAIL PROTECTED]', '', '0.0.0.0', '0', 'Wireless-802.11', '2005-10-04 01:00:33', '0', '0', '', '', '', '0', '0', '00-13-10-94-A9-14', '00-0D-93-88-5C-B9', '', '', '', '192.168.182.4', '', '0') Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): Released sql socket id: 4 Tue Oct 4 01:00:33 2005 : Debug: modsingle[accounting]: returned from sql (rlm_sql) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall[accounting]: module "sql" returns ok for request 2 Tue Oct 4 01:00:33 2005 : Debug: modsingle[accounting]: calling radutmp (rlm_radutmp) for request 2 Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '/var/log/radius/radutmp' Tue Oct 4 01:00:33 2005 : Debug: radius_xlat: '[EMAIL PROTECTED]' Tue Oct 4 01:00:33 2005 : Debug: modsingle[accounting]: returned from radutmp (rlm_radutmp) for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall[accounting]: module "radutmp" returns ok for request 2 Tue Oct 4 01:00:33 2005 : Debug: modcall: group accounting returns ok for request 2 Sending Accounting-Response of id 18 to 192.168.0.254:2052 Tue Oct 4 01:00:33 2005 : Debug: Finished request 2 Tue Oct 4 01:00:33 2005 : Debug: Going to the next request Tue Oct 4 01:00:33 2005 : Debug: Cleaning up request 2 ID 18 with timestamp 43420c71 Tue Oct 4 01:00:33 2005 : Debug: rl_next: returning NULL Tue Oct 4 01:00:33 2005 : Debug: Waking up in 6 seconds... Tue Oct 4 01:00:39 2005 : Debug: --- Walking the entire request list --- Tue Oct 4 01:00:39 2005 : Debug: Cleaning up request 1 ID 0 with timestamp 43420c71 Tue Oct 4 01:00:39 2005 : Debug: Nothing to do. Sleeping until we see a request. ----------------------------------------------------------------------- Her is an example wher the Session-Timeout i within the radcreply table: Starting RADIUS server: Tue Oct 4 01:05:27 2005 : Info: Starting - reading configuration files ... Tue Oct 4 01:05:27 2005 : Debug: reread_config: reading radiusd.conf Tue Oct 4 01:05:27 2005 : Debug: Config: including file: /etc/raddb/clients.conf Tue Oct 4 01:05:27 2005 : Debug: Config: including file: /etc/raddb/eap.conf Tue Oct 4 01:05:27 2005 : Debug: Config: including file: /etc/raddb/pointhotspot.conf Tue Oct 4 01:05:27 2005 : Debug: main: prefix = "/usr" Tue Oct 4 01:05:27 2005 : Debug: main: localstatedir = "/var" Tue Oct 4 01:05:27 2005 : Debug: main: logdir = "/var/log/radius" Tue Oct 4 01:05:27 2005 : Debug: main: libdir = "/usr/lib" Tue Oct 4 01:05:27 2005 : Debug: main: radacctdir = "/var/log/radius/radacct" Tue Oct 4 01:05:27 2005 : Debug: main: hostname_lookups = no Tue Oct 4 01:05:27 2005 : Debug: main: max_request_time = 30 Tue Oct 4 01:05:27 2005 : Debug: main: cleanup_delay = 5 Tue Oct 4 01:05:27 2005 : Debug: main: max_requests = 1024 Tue Oct 4 01:05:27 2005 : Debug: main: delete_blocked_requests = 0 Tue Oct 4 01:05:27 2005 : Debug: main: port = 0 Tue Oct 4 01:05:27 2005 : Debug: main: allow_core_dumps = no Tue Oct 4 01:05:27 2005 : Debug: main: log_stripped_names = no Tue Oct 4 01:05:27 2005 : Debug: main: log_file = "/var/log/radius/radius.log" Tue Oct 4 01:05:27 2005 : Debug: main: log_auth = no Tue Oct 4 01:05:27 2005 : Debug: main: log_auth_badpass = no Tue Oct 4 01:05:27 2005 : Debug: main: log_auth_goodpass = no Tue Oct 4 01:05:27 2005 : Debug: main: pidfile = "/var/run/radiusd/radiusd.pid" Tue Oct 4 01:05:27 2005 : Debug: main: user = "radiusd" Tue Oct 4 01:05:27 2005 : Debug: main: group = "radiusd" Tue Oct 4 01:05:27 2005 : Debug: main: usercollide = no Tue Oct 4 01:05:27 2005 : Debug: main: lower_user = "no" Tue Oct 4 01:05:27 2005 : Debug: main: lower_pass = "no" Tue Oct 4 01:05:27 2005 : Debug: main: nospace_user = "no" Tue Oct 4 01:05:27 2005 : Debug: main: nospace_pass = "no" Tue Oct 4 01:05:27 2005 : Debug: main: checkrad = "/usr/sbin/checkrad" Tue Oct 4 01:05:27 2005 : Debug: main: proxy_requests = no Tue Oct 4 01:05:27 2005 : Debug: security: max_attributes = 200 Tue Oct 4 01:05:27 2005 : Debug: security: reject_delay = 1 Tue Oct 4 01:05:27 2005 : Debug: security: status_server = no Tue Oct 4 01:05:27 2005 : Debug: main: debug_level = 0 Tue Oct 4 01:05:27 2005 : Debug: read_config_files: reading dictionary Tue Oct 4 01:05:27 2005 : Debug: read_config_files: reading naslist Tue Oct 4 01:05:27 2005 : Info: Using deprecated naslist file. Support for this will go away soon. Tue Oct 4 01:05:27 2005 : Debug: read_config_files: reading clients Tue Oct 4 01:05:27 2005 : Debug: read_config_files: reading realms Tue Oct 4 01:05:27 2005 : Debug: radiusd: entering modules setup Tue Oct 4 01:05:27 2005 : Debug: Module: Library search path is /usr/lib Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded exec Tue Oct 4 01:05:27 2005 : Debug: exec: wait = yes Tue Oct 4 01:05:27 2005 : Debug: exec: program = "(null)" Tue Oct 4 01:05:27 2005 : Debug: exec: input_pairs = "request" Tue Oct 4 01:05:27 2005 : Debug: exec: output_pairs = "(null)" Tue Oct 4 01:05:27 2005 : Debug: exec: packet_type = "(null)" Tue Oct 4 01:05:27 2005 : Info: rlm_exec: Wait=yes but no output defined. Did you mean output=none? Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated exec (exec) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded expr Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated expr (expr) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded PAP Tue Oct 4 01:05:27 2005 : Debug: pap: encryption_scheme = "crypt" Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated pap (pap) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded CHAP Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated chap (chap) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded MS-CHAP Tue Oct 4 01:05:27 2005 : Debug: mschap: use_mppe = yes Tue Oct 4 01:05:27 2005 : Debug: mschap: require_encryption = no Tue Oct 4 01:05:27 2005 : Debug: mschap: require_strong = no Tue Oct 4 01:05:27 2005 : Debug: mschap: with_ntdomain_hack = no Tue Oct 4 01:05:27 2005 : Debug: mschap: passwd = "(null)" Tue Oct 4 01:05:27 2005 : Debug: mschap: authtype = "MS-CHAP" Tue Oct 4 01:05:27 2005 : Debug: mschap: ntlm_auth = "(null)" Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated mschap (mschap) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded System Tue Oct 4 01:05:27 2005 : Debug: unix: cache = no Tue Oct 4 01:05:27 2005 : Debug: unix: passwd = "(null)" Tue Oct 4 01:05:27 2005 : Debug: unix: shadow = "/etc/shadow" Tue Oct 4 01:05:27 2005 : Debug: unix: group = "(null)" Tue Oct 4 01:05:27 2005 : Debug: unix: radwtmp = "/var/log/radius/radwtmp" Tue Oct 4 01:05:27 2005 : Debug: unix: usegroup = no Tue Oct 4 01:05:27 2005 : Debug: unix: cache_reload = 600 Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated unix (unix) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded eap Tue Oct 4 01:05:27 2005 : Debug: eap: default_eap_type = "md5" Tue Oct 4 01:05:27 2005 : Debug: eap: timer_expire = 60 Tue Oct 4 01:05:27 2005 : Debug: eap: ignore_unknown_eap_types = no Tue Oct 4 01:05:27 2005 : Debug: eap: cisco_accounting_username_bug = no Tue Oct 4 01:05:27 2005 : Debug: rlm_eap: Loaded and initialized type md5 Tue Oct 4 01:05:27 2005 : Debug: rlm_eap: Loaded and initialized type leap Tue Oct 4 01:05:27 2005 : Debug: gtc: challenge = "Password: " Tue Oct 4 01:05:27 2005 : Debug: gtc: auth_type = "PAP" Tue Oct 4 01:05:27 2005 : Debug: rlm_eap: Loaded and initialized type gtc Tue Oct 4 01:05:27 2005 : Debug: mschapv2: with_ntdomain_hack = no Tue Oct 4 01:05:27 2005 : Debug: rlm_eap: Loaded and initialized type mschapv2 Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated eap (eap) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded preprocess Tue Oct 4 01:05:27 2005 : Debug: preprocess: huntgroups = "/etc/raddb/huntgroups" Tue Oct 4 01:05:27 2005 : Debug: preprocess: hints = "/etc/raddb/hints" Tue Oct 4 01:05:27 2005 : Debug: preprocess: with_ascend_hack = no Tue Oct 4 01:05:27 2005 : Debug: preprocess: ascend_channels_per_line = 23 Tue Oct 4 01:05:27 2005 : Debug: preprocess: with_ntdomain_hack = no Tue Oct 4 01:05:27 2005 : Debug: preprocess: with_specialix_jetstream_hack = no Tue Oct 4 01:05:27 2005 : Debug: preprocess: with_cisco_vsa_hack = no Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated preprocess (preprocess) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded realm Tue Oct 4 01:05:27 2005 : Debug: realm: format = "suffix" Tue Oct 4 01:05:27 2005 : Debug: realm: delimiter = "@" Tue Oct 4 01:05:27 2005 : Debug: realm: ignore_default = no Tue Oct 4 01:05:27 2005 : Debug: realm: ignore_null = no Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated realm (suffix) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded SQL Tue Oct 4 01:05:27 2005 : Debug: sql: driver = "rlm_sql_mysql" Tue Oct 4 01:05:27 2005 : Debug: sql: server = "localhost" Tue Oct 4 01:05:27 2005 : Debug: sql: port = "" Tue Oct 4 01:05:27 2005 : Debug: sql: login = "root" Tue Oct 4 01:05:27 2005 : Debug: sql: password = "carib" Tue Oct 4 01:05:27 2005 : Debug: sql: radius_db = "poinths" Tue Oct 4 01:05:27 2005 : Debug: sql: acct_table = "radacct" Tue Oct 4 01:05:27 2005 : Debug: sql: acct_table2 = "phs_radacct" Tue Oct 4 01:05:27 2005 : Debug: sql: authcheck_table = "phs_user" Tue Oct 4 01:05:27 2005 : Debug: sql: authreply_table = "phs_radreply" Tue Oct 4 01:05:27 2005 : Debug: sql: groupcheck_table = "phs_radgroupcheck" Tue Oct 4 01:05:27 2005 : Debug: sql: groupreply_table = "phs_radgroupreply" Tue Oct 4 01:05:27 2005 : Debug: sql: usergroup_table = "phs_usergroup" Tue Oct 4 01:05:27 2005 : Debug: sql: nas_table = "phs_nas" Tue Oct 4 01:05:27 2005 : Debug: sql: dict_table = "dictionary" Tue Oct 4 01:05:27 2005 : Debug: sql: sqltrace = yes Tue Oct 4 01:05:27 2005 : Debug: sql: sqltracefile = "/var/log/radius/sqltrace.sql" Tue Oct 4 01:05:27 2005 : Debug: sql: readclients = yes Tue Oct 4 01:05:27 2005 : Debug: sql: deletestalesessions = yes Tue Oct 4 01:05:27 2005 : Debug: sql: num_sql_socks = 5 Tue Oct 4 01:05:27 2005 : Debug: sql: sql_user_name = "%{User-Name}" Tue Oct 4 01:05:27 2005 : Debug: sql: default_user_profile = "" Tue Oct 4 01:05:27 2005 : Debug: sql: query_on_not_found = no Tue Oct 4 01:05:27 2005 : Debug: sql: authorize_check_query = "SELECT user_id,user_username,user_attribute,user_value,user_op FROM phs_user WHERE user_username = '%{SQL-User-Name}' ORDER BY user_id" Tue Oct 4 01:05:27 2005 : Debug: sql: authorize_reply_query = "SELECT radreply_id,radreply_username,radreply_attribute,radreply_value,radreply_op FROM phs_radreply WHERE radreply_username = '%{SQL-User-Name}' ORDER BY radreply_id" Tue Oct 4 01:05:27 2005 : Debug: sql: authorize_group_check_query = "SELECT phs_radgroupcheck.radgroupcheck_id,phs_radgroupcheck.radgroupcheck_groupname ,phs_radgroupcheck.radgroupcheck_attribute,phs_radgroupcheck.radgroupcheck_v alue,phs_radgroupcheck.radgroupcheck_op FROM phs_radgroupcheck,phs_usergroup WHERE phs_usergroup.usergroup_username = '%{SQL-User-Name}' AND phs_usergroup.usergroup_groupname = phs_radgroupcheck.radgroupcheck_groupname ORDER BY phs_radgroupcheck.radgroupcheck_id" Tue Oct 4 01:05:27 2005 : Debug: sql: authorize_group_reply_query = "SELECT phs_radgroupreply.radgroupreply_id,phs_radgroupreply.radgroupreply_groupname ,phs_radgroupreply.radgroupreply_attribute,phs_radgroupreply.radgroupreply_v alue,phs_radgroupreply.radgroupreply_op FROM phs_radgroupreply,phs_usergroup WHERE phs_usergroup.usergroup_username = '%{SQL-User-Name}' AND phs_usergroup.usergroup_groupname = phs_radgroupreply.radgroupreply_groupname ORDER BY phs_radgroupreply.radgroupreply_id" Tue Oct 4 01:05:27 2005 : Debug: sql: accounting_onoff_query = "UPDATE phs_radacct SET radacct_stoptime='%S', radacct_sessiontime=unix_timestamp('%S') - unix_timestamp(radacct_starttime), radacct_terminatecause='%{Acct-Terminate-Cause}', radacct_stopdelay = '%{Acct-Delay-Time}' WHERE radacct_sessiontime=0 AND radacct_stoptime=0 AND radacct_nas_ipaddress= '%{NAS-IP-Address}' AND radacct_starttime <= '%S'" Tue Oct 4 01:05:27 2005 : Debug: sql: accounting_update_query = "UPDATE phs_radacct ? SET radacct_framedipaddress = '%{Framed-IP-Address}', ? radacct_sessiontime = '%{Acct-Session-Time}', ? radacct_inputoctets = '%{Acct-Input-Octets}', ? radacct_outputoctets = '%{Acct-Output-Octets}' ? WHERE radacct_session_id = '%{Acct-Session-Id}' ? AND radacct_username = '%{SQL-User-Name}' ? AND radacct_nas_ipaddress= '%{NAS-IP-Address}'" Tue Oct 4 01:05:27 2005 : Debug: sql: accounting_update_query_alt = "INSERT into phs_radacct (radacct_session_id, radacct_unique_id, radacct_username, radacct_realm, radacct_nas_ipaddress, radacct_nas_portid, radacct_nas_porttype, radacct_starttime, radacct_sessiontime, radacct_authentic, radacct_connectinfo_start, radacct_inputoctets, radacct_outputoctets, radacct_called_stationid, radacct_calling_stationid, radacct_servicetype, radacct_framedprotocol, radacct_framedipaddress, radacct_startdelay) 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')" Tue Oct 4 01:05:27 2005 : Debug: sql: accounting_start_query = "INSERT into phs_radacct (radacct_session_id, radacct_unique_id, radacct_username, radacct_realm, radacct_nas_ipaddress, radacct_nas_portid, radacct_nas_porttype, radacct_starttime, radacct_stoptime, radacct_sessiontime, radacct_authentic, radacct_connectinfo_start, radacct_connectinfo_stop, radacct_inputoctets, radacct_outputoctets, radacct_called_stationId, radacct_calling_stationId, radacct_terminatecause, radacct_servicetype, radacct_framedprotocol, radacct_framedipaddress, radacct_startdelay, radacct_stopdelay) 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')" Tue Oct 4 01:05:27 2005 : Debug: sql: accounting_start_query_alt = "UPDATE phs_radacct SET radacct_starttime = '%S', radacct_startdelay = '%{Acct-Delay-Time}', radacct_connectinfo_start = '%{Connect-Info}' WHERE radacct_session_id = '%{Acct-Session-Id}' AND radacct_username = '%{SQL-User-Name}' AND radacct_nas_ipaddress = '%{NAS-IP-Address}'" Tue Oct 4 01:05:27 2005 : Debug: sql: accounting_stop_query = "UPDATE phs_radacct SET radacct_stoptime = '%S', radacct_sessiontime = '%{Acct-Session-Time}', radacct_inputoctets = '%{Acct-Input-Octets}', radacct_outputoctets = '%{Acct-Output-Octets}', radacct_terminatecause = '%{Acct-Terminate-Cause}', radacct_stopdelay = '%{Acct-Delay-Time}', radacct_connectinfo_stop = '%{Connect-Info}' WHERE radacct_session_id = '%{Acct-Session-Id}' AND radacct_username = '%{SQL-User-Name}' AND radacct_nas_ipaddress = '%{NAS-IP-Address}'" Tue Oct 4 01:05:27 2005 : Debug: sql: accounting_stop_query_alt = "INSERT into phs_radacct (radacct_session_id, radacct_unique_id, radacct_username, radacct_realm, radacct_nas_ipaddress, radacct_nas_portid, radacct_nas_porttype, radacct_starttime, radacct_stoptime, radacct_sessiontime, radacct_authentic, radacct_connectinfo_start, radacct_connectinfo_stop, radacct_inputoctets, radacct_outputoctets, radacct_called_stationId, radacct_calling_stationid, radacct_terminatecause, radacct_servicetype, radacct_framedprotocol, radacct_framedipaddress, radacct_startdelay, radacct_stopdelay) 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}')" Tue Oct 4 01:05:27 2005 : Debug: sql: group_membership_query = "SELECT usergroup_groupname FROM phs_usergroup WHERE usergroup_username='%{SQL-User-Name}'" Tue Oct 4 01:05:27 2005 : Debug: sql: connect_failure_retry_delay = 60 Tue Oct 4 01:05:27 2005 : Debug: sql: simul_count_query = "SELECT COUNT(*) FROM phs_radacct WHERE radacct_username='%{SQL-User-Name}' AND radacct_stoptime = 0" Tue Oct 4 01:05:27 2005 : Debug: sql: simul_verify_query = "SELECT radacct_id, radacct_session_id, radacct_username, radacct_nas_ipaddress, radacct_nas_portid, radacct_framedipaddress, radacct_calling_stationid, radacct_framedprotocol FROM phs_radacct WHERE radacct_username='%{SQL-User-Name}' AND radacct_stoptime = 0" Tue Oct 4 01:05:27 2005 : Debug: sql: postauth_table = "phs_radpostauth" Tue Oct 4 01:05:27 2005 : Debug: sql: postauth_query = "INSERT into phs_radpostauth (radpostauth_id, radpostauth_user, radpostauth_pass, radpostauth_reply, radpostauth_mdate) values ('', '%{User-Name}', '%{User-Password:-Chap-Password}', '%{reply:Packet-Type}', NOW())" Tue Oct 4 01:05:27 2005 : Debug: sql: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Tue Oct 4 01:05:27 2005 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Tue Oct 4 01:05:27 2005 : Info: rlm_sql (sql): Attempting to connect to [EMAIL PROTECTED]:/poinths Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): starting 0 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0 Tue Oct 4 01:05:27 2005 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Connected new DB handle, #0 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): starting 1 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1 Tue Oct 4 01:05:27 2005 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Connected new DB handle, #1 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): starting 2 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2 Tue Oct 4 01:05:27 2005 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Connected new DB handle, #2 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): starting 3 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3 Tue Oct 4 01:05:27 2005 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Connected new DB handle, #3 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): starting 4 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4 Tue Oct 4 01:05:27 2005 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Connected new DB handle, #4 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): - generate_sql_clients Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Query: SELECT * FROM phs_nas Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Reserving sql socket id: 4 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql_mysql: query: SELECT * FROM phs_nas Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Read entry [EMAIL PROTECTED],shortname=moin,secret=fjyr5r89ka2mqkb7di Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Adding client 192.168.0.244 (moin) to clients list Tue Oct 4 01:05:27 2005 : Error: rlm_sql (sql): No short name found for row 2 Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Read entry [EMAIL PROTECTED],shortname=Norm,secret=fjyr5r89ka2mqkb7di Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Adding client 192.168.0.254 (Norm) to clients list Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Read entry nasname=192.168.0.3,shortname=ntradping,secret=fjyr5r89ka2mqkb7di Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Adding client 192.168.0.3 (ntradping) to clients list Tue Oct 4 01:05:27 2005 : Debug: rlm_sql (sql): Released sql socket id: 4 Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated sql (sql) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded files Tue Oct 4 01:05:27 2005 : Debug: files: usersfile = "/etc/raddb/users" Tue Oct 4 01:05:27 2005 : Debug: files: acctusersfile = "/etc/raddb/acct_users" Tue Oct 4 01:05:27 2005 : Debug: files: preproxy_usersfile = "/etc/raddb/preproxy_users" Tue Oct 4 01:05:27 2005 : Debug: files: compat = "no" Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated files (files) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded Acct-Unique-Session-Id Tue Oct 4 01:05:27 2005 : Debug: acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated acct_unique (acct_unique) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded detail Tue Oct 4 01:05:27 2005 : Debug: detail: detailfile = "/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Tue Oct 4 01:05:27 2005 : Debug: detail: detailperm = 384 Tue Oct 4 01:05:27 2005 : Debug: detail: dirperm = 493 Tue Oct 4 01:05:27 2005 : Debug: detail: locking = no Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated detail (detail) Tue Oct 4 01:05:27 2005 : Debug: Module: Loaded radutmp Tue Oct 4 01:05:27 2005 : Debug: radutmp: filename = "/var/log/radius/radutmp" Tue Oct 4 01:05:27 2005 : Debug: radutmp: username = "%{User-Name}" Tue Oct 4 01:05:27 2005 : Debug: radutmp: case_sensitive = yes Tue Oct 4 01:05:27 2005 : Debug: radutmp: check_with_nas = yes Tue Oct 4 01:05:27 2005 : Debug: radutmp: perm = 384 Tue Oct 4 01:05:27 2005 : Debug: radutmp: callerid = yes Tue Oct 4 01:05:27 2005 : Debug: Module: Instantiated radutmp (radutmp) Tue Oct 4 01:05:27 2005 : Debug: Listening on authentication *:1812 Tue Oct 4 01:05:27 2005 : Debug: Listening on accounting *:1813 Tue Oct 4 01:05:27 2005 : Info: Ready to process requests. ----------------------------------------------------------------------- -----Original Message----- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Alan DeKok Sent: Monday, October 03, 2005 8:22 PM To: FreeRadius users mailing list Subject: Re: expr in SQL not working "Gunther" <[EMAIL PROTECTED]> wrote: > Anyhow, if I can get within the rad_reply table e.g. `%{expr:10+100)` > working to set my Session-Timeout ... I would be quite happy. Post the complete debug log for one Accounting-Request packet. Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html