Hi everyone,
We are using Freeradius CVS snapshot dated 10-23-2002 running on a Linux
box.
Using MySQL for accounting we noticed that if Freeradius receives an
accounting stop packet without having received a start packet it will first
try to update an existing record in the radacct database. Since there is no
existing record it will then insert a new record. This includes all the
information for the user session neccessary for billing and tracking
information. However in case Freeradius receives an update packet it
will only try to update an existing record. Failing that it will then quit
trying and the module returns an ok status. This results in no information
being available about the session until the session ends. This is
unfortunate, especially for keeping track of usage for DSL users which can
be connnected for days on end. We are working on a fix but in case someone
already has this solved... :-)
Here is the debug output for a session using radiusd -xx . We generated a
start packet, deleted the info from the database and then sent a update
packet followed by a stop packet from the NAS. The first request resulted
in no record being inserted since the sql query finds no match in the
database. The second request first tries to do an update and failing that
does an insert. No modifications to sql.conf except username and pass for
the connection and adding FramedIPAddress to the insert query for the stop
record (see my previous post today).
************************************************First request (update
packet)******************
rad_recv: Accounting-Request packet from host xxx.xxx.xxx.xxx:1646, id=57,
length=116
Thread 3 assigned request 17
--- Walking the entire request list ---
Threads: total/active/spare threads = 5/1/4
Waking up in 5 seconds...
Thread 3 handling request 17, (4 handled so far)
NAS-IP-Address = xxx.xxx.xxx.xxx
NAS-Port = 27
NAS-Port-Type = Async
User-Name = "user"
Called-Station-Id = "1234567"
Calling-Station-Id = "7654321"
Acct-Status-Type = Alive
Acct-Authentic = RADIUS
Service-Type = Framed-User
Acct-Session-Id = "00000073"
Framed-Protocol = PPP
Framed-IP-Address = yyy.yyy.yyy.yyy
Acct-Delay-Time = 0
modcall: entering group preacct
modcall[preacct]: module "preprocess" returns noop
rlm_realm: No '@' in User-Name = "user", looking up realm NULL
rlm_realm: No such realm NULL
modcall[preacct]: module "suffix" returns noop
modcall[preacct]: module "files" returns noop
modcall: group preacct returns noop
modcall: entering group accounting
rlm_acct_unique: WARNING: Attribute 87 was not found in request, unique ID
MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address =
xxx.xxx.xxx.xxx,NAS-IP-Address = xxx.xxx.xxx.xxx,Acct-Session-Id =
"00000073",User-Name = "user"'
rlm_acct_unique: Acct-Unique-Session-ID = "d7da8e2d7080ab7a".
modcall[accounting]: module "acct_unique" returns ok
radius_xlat:
'/usr/local/var/log/radius/radacct/xxx.xxx.xxx.xxx/detail-20021031'
rlm_detail:
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands
to /usr/local/var/log/radius/radacct/xxx.xxx.xxx.xxx/detail-20021031
modcall[accounting]: module "detail" returns ok
radius_xlat: 'ingvarbjarna'
modcall[accounting]: module "radutmp" returns ok
radius_xlat: 'ingvarbjarna'
sql_set_user: escaped user --> 'ingvarbjarna'
radius_xlat: 'UPDATE radacct SET FramedIPAddress = 'yyy.yyy.yyy.yyy' WHERE
AcctSessionId = '00000073' AND UserName = 'user' AND NASIPAddress=
'xxx.xxx.xxx.xxx' AND AcctStopTime = 0'
rlm_sql: Reserving sql socket id: 1
rlm_sql: Released sql socket id: 1
modcall[accounting]: module "sql" returns ok
modcall: group accounting returns ok
Sending Accounting-Response of id 57 to xxx.xxx.xxx.xxx:1646
Finished request 17
Going to the next request
Thread 3 waiting to be assigned a request
--- Walking the entire request list ---
Threads: total/active/spare threads = 5/0/5
Cleaning up request 17 ID 57 with timestamp 3dc11b20
Nothing to do. Sleeping until we see a request.
****************************************************************************
*************
******************************************second request (stop
packet)*************************
rad_recv: Accounting-Request packet from host xxx.xxx.xxx.xxx:1646, id=58,
length=146
Thread 4 assigned request 18
--- Walking the entire request list ---
Threads: total/active/spare threads = 5/1/4
Waking up in 5 seconds...
Thread 4 handling request 18, (4 handled so far)
NAS-IP-Address = xxx.xxx.xxx.xxx
NAS-Port = 27
NAS-Port-Type = Async
User-Name = "user"
Called-Station-Id = "1234567"
Calling-Station-Id = "7654321"
Acct-Status-Type = Stop
Acct-Authentic = RADIUS
Service-Type = Framed-User
Acct-Session-Id = "00000073"
Framed-Protocol = PPP
Framed-IP-Address = yyy.yyy.yyy.yyy
Acct-Input-Octets = 778
Acct-Output-Octets = 770
Acct-Input-Packets = 7
Acct-Output-Packets = 7
Acct-Session-Time = 419
Acct-Delay-Time = 0
modcall: entering group preacct
modcall[preacct]: module "preprocess" returns noop
rlm_realm: No '@' in User-Name = "user", looking up realm NULL
rlm_realm: No such realm NULL
modcall[preacct]: module "suffix" returns noop
modcall[preacct]: module "files" returns noop
modcall: group preacct returns noop
modcall: entering group accounting
rlm_acct_unique: WARNING: Attribute 87 was not found in request, unique ID
MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address =
xxx.xxx.xxx.xxx,NAS-IP-Address = xxx.xxx.xxx.xxx,Acct-Session-Id =
"00000073",User-Name = "user"'
rlm_acct_unique: Acct-Unique-Session-ID = "d7da8e2d7080ab7a".
modcall[accounting]: module "acct_unique" returns ok
radius_xlat:
'/usr/local/var/log/radius/radacct/xxx.xxx.xxx.xxx/detail-20021031'
rlm_detail:
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands
to /usr/local/var/log/radius/radacct/xxx.xxx.xxx.xxx/detail-20021031
modcall[accounting]: module "detail" returns ok
radius_xlat: 'user'
modcall[accounting]: module "radutmp" returns ok
radius_xlat: 'user'
sql_set_user: escaped user --> 'user'
radius_xlat: 'UPDATE radacct SET AcctStopTime = '2002-10-31 12:01:42',
AcctSessionTime = '419', AcctInputOctets = '778', AcctOutputOctets = '770',
AcctTerminateCause = '', AcctStopDelay = '0', ConnectInfo_stop = '',
FramedIPAddress = 'yyy.yyy.yyy.yyy' WHERE AcctSessionId = '00000073' AND
UserName = 'user' AND NASIPAddress = 'xxx.xxx.xxx.xxx' AND AcctStopTime = 0'
rlm_sql: Reserving sql socket id: 0
radius_xlat: 'INSERT into radacct (RadAcctId, AcctSessionId, AcctUniqueId,
UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime,
AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start,
ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId,
CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol,
FramedIPAddress, AcctStartDelay, AcctStopDelay) values('', '00000073',
'd7da8e2d7080ab7a', 'user', '', 'xxx.xxx.xxx.xxx', '27', 'Async', '0',
'2002-10-31 12:01:42', '419', 'RADIUS', '', '', '778', '770', '1234567',
'7654321', '', 'Framed-User', 'PPP', 'yyy.yyy.yyy.yyy', '0', '0')'
rlm_sql: Released sql socket id: 0
modcall[accounting]: module "sql" returns ok
modcall: group accounting returns ok
Sending Accounting-Response of id 58 to xxx.xxx.xxx.xxx:1646
Finished request 18
Going to the next request
Thread 4 waiting to be assigned a request
--- Walking the entire request list ---
Threads: total/active/spare threads = 5/0/5
Cleaning up request 18 ID 58 with timestamp 3dc11ba6
Nothing to do. Sleeping until we see a request.
****************************************************************************
*****
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
