expr in SQL not working
Gunther
freeradius at caribsms.com
Tue Oct 4 07:11:02 CEST 2005
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 = "pointhot01 at norm"
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 = "pointhot01 at norm"
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 = "gunther at norm"
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 = "pointhot01 at norm"
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 = "gunther at norm"
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: 'gunther at norm'
Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): sql_set_user escaped user
--> 'gunther at norm'
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 = 'gunther at norm' 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 = 'gunther at norm' 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 =
'gunther at norm' 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 =
'gunther at norm' 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 = 'gunther at norm' 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 = 'gunther at norm' 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 =
'gunther at norm' 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 =
'gunther at norm' 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: 'gunther at norm'
Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): sql_set_user escaped user
--> 'gunther at norm'
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='gunther at norm''
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='gunther at norm'
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: 'gunther at norm'
Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): sql_set_user escaped user
--> 'gunther at norm'
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 ('', 'gunther at norm', '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 ('',
'gunther at norm', '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 ('', 'gunther at norm',
'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 = "gunther at norm"
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 = "pointhot01 at norm"
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 = "gunther at norm"'
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 = "gunther at norm"
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: 'gunther at norm'
Tue Oct 4 01:00:33 2005 : Debug: rlm_sql (sql): sql_set_user escaped user
--> 'gunther at norm'
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', 'gunther at norm', '',
'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', 'gunther at norm', '', '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: 'gunther at norm'
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
root at localhost:/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
nasname=pointhot_1 at tch,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
nasname=pointhot01 at norm,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: freeradius-users-bounces at lists.freeradius.org
[mailto:freeradius-users-bounces at lists.freeradius.org] 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" <freeradius at caribsms.com> 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
More information about the Freeradius-Users
mailing list