Freeradius - MySQL Update problem

Mon Aug 6 16:13:12 CEST 2007

Hello Ivan,

Mon, 06 Aug 2007 12:52:20 +0100, you wrote:
From: <tnt at kalik.co.yu>

>1. Send debug with the Accounting-Request
>2. Create an extra field for that attribute (IP address is varchar(15)
>type) to the radaact table and add the field and value to the query (so
>it's definitely different.
>
>Ivan Kalik
>Kalik Informatika ISP

Here is more debug output with accounting request:

Finished request 100
Going to the next request
Waking up in 5 seconds...
rad_recv: Accounting-Request packet from host n.a.s.1:1646, id=239,
length=531
        Acct-Session-Id = "0024F8FF"
        Calling-Station-Id = "442098765432"
        Called-Station-Id = "0002561234567"
        h323-setup-time = "h323-setup-time=16:53:14.471 GMT+3 Mon Aug 6 2007"
        h323-gw-id = "h323-gw-id=Rotelkom_Gateway.www.nas.co.ug"
        h323-conf-id = "h323-conf-id=B4550CDC FAA011D6 887DF94C E05F1EEE"
        h323-call-origin = "h323-call-origin=answer"
        h323-call-type = "h323-call-type=VoIP"
        Cisco-AVPair = "h323-incoming-conf-id=B4550CDC FAA011D6 887DF94C
E05F1EEE"
        Cisco-AVPair = "subscriber=Unknown"
        Cisco-AVPair = "session-protocol=cisco"
        Cisco-AVPair = "gw-rxd-cdn=ton:0,npi:1,#:0002561234567"
        User-Name = "rem.ote.add.ress"
        Cisco-AVPair = "connect-progress=Call Up"
        Acct-Authentic = 0
        Acct-Status-Type = Start
        Service-Type = Login-User
        NAS-IP-Address = n.a.s.1
        Acct-Delay-Time = 10
  Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 101
  modcall[preacct]: module "preprocess" returns noop for request 101
rlm_acct_unique: WARNING: Attribute NAS-Port was not found in request, unique
ID MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address = n.a.s.1,NAS-IP-Address =
n.a.s.1,Acct-Session-Id = "0024F8FF",User-Name = "rem.ote.add.ress"'
rlm_acct_unique: Acct-Unique-Session-ID = "ecaef4ac9b6cbafc".
  modcall[preacct]: module "acct_unique" returns ok for request 101
    rlm_realm: No '@' in User-Name = "rem.ote.add.ress", looking up realm
NULL
    rlm_realm: No such realm "NULL"
  modcall[preacct]: module "suffix" returns noop for request 101
  modcall[preacct]: module "files" returns noop for request 101
modcall: leaving group preacct (returns ok) for request 101
  Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 101
radius_xlat:  '/var/log/radius/radacct/n.a.s.1/detail-20070806'
rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d
expands to /var/log/radius/radacct/n.a.s.1/detail-20070806
  modcall[accounting]: module "detail" returns ok for request 101
  modcall[accounting]: module "unix" returns noop for request 101
radius_xlat:  '/var/log/radius/radutmp'
radius_xlat:  'rem.ote.add.ress'
  rlm_radutmp: No NAS-Port seen.  Cannot do anything.
  rlm_radumtp: WARNING: checkrad will probably not work!
  modcall[accounting]: module "radutmp" returns noop for request 101
radius_xlat:  'rem.ote.add.ress'
rlm_sql (sql): sql_set_user escaped user --> 'rem.ote.add.ress'
radius_xlat:  'INSERT into radacct (AcctSessionId, AcctUniqueId, UserName,
Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime,
AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop,
AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId,
AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress,
AcctStartDelay, AcctStopDelay) values('0024F8FF', 'ecaef4ac9b6cbafc',
'rem.ote.add.ress', '', 'n.a.s.1', '', '', '2007-08-06 16:53:36', '0', '0',
'0', '', '', '0', '0', '0002561234567', '442098765432', '', '', '', '', '10',
'0')'
rlm_sql (sql): Reserving sql socket id: 8
rlm_sql (sql): Released sql socket id: 8
  modcall[accounting]: module "sql" returns ok for request 101
modcall: leaving group accounting (returns ok) for request 101
Sending Accounting-Response of id 239 to n.a.s.1 port 1646
Finished request 101
Going to the next request
Waking up in 5 seconds...
rad_recv: Accounting-Request packet from host n.a.s.1:1646, id=240,
length=542
        Acct-Session-Id = "0024F901"
        Calling-Station-Id = "442098765432"
        Called-Station-Id = "0002561234567"
        h323-setup-time = "h323-setup-time=16:53:14.519 GMT+3 Mon Aug 6 2007"
        h323-gw-id = "h323-gw-id=Rotelkom_Gateway.www.nas.co.ug"
        h323-conf-id = "h323-conf-id=B4550CDC FAA011D6 887DF94C E05F1EEE"
        h323-call-origin = "h323-call-origin=originate"
        h323-call-type = "h323-call-type=Telephony"
        Cisco-AVPair = "h323-incoming-conf-id=B4550CDC FAA011D6 887DF94C
E05F1EEE"
        Cisco-AVPair = "subscriber=Unknown"
        Cisco-AVPair = "gw-rxd-cdn=ton:0,npi:1,#:0002561234567"
        User-Name = "rem.ote.add.ress"
        Cisco-AVPair = "connect-progress=Call Up"
        Acct-Authentic = 0
        Acct-Status-Type = Start
        NAS-Port-Type = Async
        Cisco-NAS-Port = "ISDN 1/5:D:28"
        NAS-Port = 0
        Service-Type = Login-User
        NAS-IP-Address = n.a.s.1
        Acct-Delay-Time = 10
  Processing the preacct section of radiu
mail:~ # killall radius
radius: no process killed
mail:~ # /etc/init.d/radiusd start
Starting RADIUS daemon                                                done
mail:~ # less radiusdebug
        Cisco-AVPair = "lowater-playout-delay=0 ms"
        Cisco-AVPair = "gapfill-with-interpolation=0 ms"
        Cisco-AVPair = "gapfill-with-prediction=0 ms"
        Cisco-AVPair = "gapfill-with-redundancy=0 ms"
        Cisco-AVPair = "gapfill-with-silence=0 ms"
        Cisco-AVPair = "early-packets=0"
        Cisco-AVPair = "late-packets=0"
        Cisco-AVPair = "lost-packets=0"
        Acct-Authentic = 0
        Acct-Status-Type = Stop
        Service-Type = Login-User
        NAS-IP-Address = n.a.s.1
        Acct-Delay-Time = 10
  Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 0
  modcall[preacct]: module "preprocess" returns noop for request 0
rlm_acct_unique: WARNING: Attribute NAS-Port was not found in request, unique
ID MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address = n.a.s.1,NAS-IP-Address =
n.a.s.1,Acct-Session-Id = "0024F503",User-Name = "85.31.4
8.5"'
rlm_acct_unique: Acct-Unique-Session-ID = "85c05e6f00c27cfe".
  modcall[preacct]: module "acct_unique" returns ok for request 0
    rlm_realm: No '@' in User-Name = "rem.ote.add.ress", looking up realm
NULL
    rlm_realm: No such realm "NULL"
  modcall[preacct]: module "suffix" returns noop for request 0
  modcall[preacct]: module "files" returns noop for request 0
modcall: leaving group preacct (returns ok) for request 0
  Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 0
radius_xlat:  '/var/log/radius/radacct/n.a.s.1/detail-20070806'
rlm_detail: /var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d
expands to /var/log/radius/radacct/n.a.s.1/detail-20070806
  modcall[accounting]: module "detail" returns ok for request 0
  modcall[accounting]: module "unix" returns noop for request 0
radius_xlat:  '/var/log/radius/radutmp'
radius_xlat:  'rem.ote.add.ress'
  rlm_radutmp: No NAS-Port seen.  Cannot do anything.
  rlm_radumtp: WARNING: checkrad will probably not work!
  modcall[accounting]: module "radutmp" returns noop for request 0
radius_xlat:  'rem.ote.add.ress'
rlm_sql (sql): sql_set_user escaped user --> 'rem.ote.add.ress'
radius_xlat:  'UPDATE radacct SET AcctStopTime = '2007-08-06 16:43:42',
AcctSessionTime = '0', AcctInputOctets = '0', AcctOutputOctets = '4
60', AcctTerminateCause = '', AcctStopDelay = '10', ConnectInfo_stop = ''
WHERE AcctSessionId = '0024F503' AND UserName = 'rem.ote.add.ress' AND
NASIPAddress = 'n.a.s.1''
rlm_sql (sql): Reserving sql socket id: 9
radius_xlat:  'stop packet with zero session length. [user
'rem.ote.add.ress', nas 'n.a.s.1']'
rlm_sql (sql) in sql_accounting: stop packet with zero session length. [user
'rem.ote.add.ress', nas 'n.a.s.1']
rlm_sql (sql): Released sql socket id: 9
radius_xlat:  'INSERT into radacct (AcctSessionId, AcctUniqueId, UserName,
Realm, NASIPAddress,NASPortId, NASPortType, AcctStartTime, AcctS
topTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_stop,
AcctInputOctets, AcctOutputOctets, CalledStationId, CallingSt
ationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress,
AcctStartDelay, AcctStopDelay) values('0024F503', '85c05e6f00c27
cfe', 'rem.ote.add.ress', '', 'n.a.s.1', '', '', DATE_SUB('2007-08-06
16:43:42', INTERVAL (0 + 10) SECOND), '2007-08-06 16:43:42', '0', '0',
 '', '', '0', '460', '00025698765432', '', '', 'rem.ote.add.ress', '',
'rem.ote.add.ress', '0', '10')'
rlm_sql (sql): Released sql socket id: 9
  modcall[accounting]: module "sql" returns noop for request 0
modcall: leaving group accounting (returns ok) for request 0
Sending Accounting-Response of id 119 to n.a.s.1 port 1646
Finished request 0
Going to the next request

n.a.s.1 is the IP address of my local NAS and rem.ote.add.ress is the IP
address of the remote router.

Regards

Timothy