BUGREPORT: SQL module fails on every CISCO reboot

Fri Jun 3 11:39:12 CEST 2005

Hi!

 I'm using a CISCO NAS with 240 modem lines and
SQL/MySQL as accounting module.

 FreeRADIUS CVS fails on every CISCO reboot !

 As I found, CISCO send 240 packets with:
"Acct-Status-Type = Stop"
"Acct-Terminate-Cause = Lost-Carrier"
in accounting requests (1 per line) in about 5 mS on reboot
and FreeRADIUS dies on this massive bombing.

 May be, this is CISCO IOS error, but FreeRADIUS should
(must) tolerate it...

 As far as I understand, SQL module segfaults when SQL
connection pool is over. Seems, pooling mechanism is bogus.

=======
preacct {
        preprocess
}
accounting {
    radutmp
    sql
}
=======

 SQL module creates a pool :

....
rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to radius at localhost:/radius
rlm_sql (sql): starting 0
rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
rlm_sql_mysql: Starting connect to MySQL server for #0
rlm_sql (sql): Connected new DB handle, #0
rlm_sql (sql): starting 1
rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
rlm_sql_mysql: Starting connect to MySQL server for #1
rlm_sql (sql): Connected new DB handle, #1
rlm_sql (sql): starting 2
rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
rlm_sql_mysql: Starting connect to MySQL server for #2
rlm_sql (sql): Connected new DB handle, #2
rlm_sql (sql): starting 3
rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
rlm_sql_mysql: Starting connect to MySQL server for #3
rlm_sql (sql): Connected new DB handle, #3
rlm_sql (sql): starting 4
rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
rlm_sql_mysql: Starting connect to MySQL server for #4
rlm_sql (sql): Connected new DB handle, #4
Module: Instantiated sql (sql)
....
....
   CISCO produces heavy load on reboot :
...
...
Thread 1 waiting to be assigned a request
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=163, length=109
Threads: total/active/spare threads = 18/12/6
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=164, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=165, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=166, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=167, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=168, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=169, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=170, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=171, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=172, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=173, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=174, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=175, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=176, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=177, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=178, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=179, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=180, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=181, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=182, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=183, length=109
Waking up in 30 seconds...
rad_recv: Accounting-Request packet from host 192.168.1.36 port 1646, id=184, length=109
Waking up in 30 seconds...
...
...
    SQL segfaults after SQL_DOWN:
...
...
Going to the next request
Thread 15 waiting to be assigned a request
Thread 15 got semaphore
Thread 15 handling request 44, (2 handled so far)
        Acct-Session-Id = "000000AF"
        Acct-Session-Time = 0
        Acct-Input-Octets = 0
        Acct-Output-Octets = 0
        Acct-Input-Packets = 0
        Acct-Output-Packets = 0
        Acct-Terminate-Cause = Lost-Carrier
        Acct-Status-Type = Stop
        NAS-Port = 175
        NAS-Port-Type = Async
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('0000009C', '3161648c243dee0b', '', '', '192.168.1.36', '156', 'Async', DATE_SUB('2005-06-03 
11:31:39', INTERVAL (0 + 0) SECOND), '2005-06-03 11:31:39', '0', '', '', '', '0', '0', '', 'async', 'Lost-Carrier', 'Framed-User', 
'', '', '0', '0')'
rlm_sql (sql): Reserving sql socket id: 3
radius_xlat:  'rlm_sql: Stop packet with zero session length.  (user '', nas '192.168.1.36')'
rlm_sql: Stop packet with zero session length.  (user '', nas '192.168.1.36')
rlm_sql (sql): Released sql socket id: 0
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('000000A1', 'ee06eeee60d67938', '', '', '192.168.1.36', '161', 'Async', DATE_SUB('2005-06-03 
11:31:39', INTERVAL (0 + 0) SECOND), '2005-06-03 11:31:39', '0', '', '', '', '0', '0', '', 'async', 'Lost-Carrier', 'Framed-User', 
'', '', '0', '0')'
        Calling-Station-Id = "async"
        Service-Type = Framed-User
        NAS-IP-Address = 192.168.1.36
        Acct-Delay-Time = 0
  Processing the preacct section of radiusd.conf
modcall: entering group preacct for request 44
  modcall[preacct]: module "preprocess" returns ok for request 44
rlm_acct_unique: WARNING: Attribute Client-IP-Address was not found in request, unique ID MAY be inconsistent
rlm_acct_unique: WARNING: Attribute User-Name was not found in request, unique ID MAY be inconsistent
rlm_acct_unique: Hashing 'NAS-Port = 175,,NAS-IP-Address = 192.168.1.36,Acct-Session-Id = "000000AF",'
rlm_acct_unique: Acct-Unique-Session-ID = "c49f73d50a4c8f2e".

  modcall[preacct]: module "acct_unique" returns ok for request 44
modcall: leaving group preacct (returns ok) for request 44
  Processing the accounting section of radiusd.conf
modcall: entering group accounting for request 44
radius_xlat:  '/opt/var/log/radius/radutmp'
radius_xlat:  ''
rlm_radutmp: Logout for NAS credit_test port 175, but no Login record
  modcall[accounting]: module "radutmp" returns ok for request 44
radius_xlat:  ''
radius_xlat:  'UPDATE radacct SET AcctStopTime = '2005-06-03 11:31:39', AcctSessionTime = '0', AcctInputOctets = '0', 
AcctOutputOctets = '0', AcctTerminateCause = 'Lost-Carrier', AcctStopDelay = '0', ConnectInfo_stop = '' WHERE AcctSessionId = 
'000000AF' AND UserName = '' AND NASIPAddress = '192.168.1.36''
rlm_sql (sql): Reserving sql socket id: 2
        Acct-Session-Id = "00000095"
        Acct-Session-Time = 0
        Acct-Input-Octets = 0
        Acct-Output-Octets = 0
        Acct-Input-Packets = 0
        Acct-Output-Packets = 0
        Acct-Terminate-Cause = Lost-Carrier
rlm_sql_mysql: MYSQL check_error: 2013, returning SQL_DOWN
rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
rlm_sql_mysql: Starting connect to MySQL server for #2
        Acct-Status-Type = Stop
        NAS-Port = 122
        NAS-Port-Type = Async
        Calling-Station-Id = "async"
        Service-Type = Framed-User
        NAS-IP-Address = 192.168.1.36
        Acct-Delay-Time = 0
  Processing the preacct section of radiusd.conf
Segmentation fault

 SQL returninig SQL_DOWN

rlm_sql_mysql: MYSQL check_error: 2013, returning SQL_DOWN

 Is there any way to avoid insertion of this empty records ?

--
-=AV=-