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@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=-
Alexander Voropay wrote:
I'm using a CISCO NAS with 240 modem lines and SQL/MySQL as accounting module. [...] As far as I understand, SQL module segfaults when SQL connection pool is over. Seems, pooling mechanism is bogus.
Thanks for the report. Please specify the version of FreeRADIUS you're using. You could also post the output of gdb, as explained on the website: http://bugs.freeradius.org/ -- Nicolas Baradakis
"Nicolas Baradakis" <nbk@sitadelle.com> wrote:
I'm using a CISCO NAS with 240 modem lines and SQL/MySQL as accounting module. [...] As far as I understand, SQL module segfaults when SQL connection pool is over. Seems, pooling mechanism is bogus.
Thanks for the report. Please specify the version of FreeRADIUS you're using. You could also post the output of gdb,
FreeRADIUS is CVS snapshot ~ 29-may-2005 Nothing informative in gdb output. May be, "rlm_sql" module is not thread-safe ? It makes ~150 records (of 240) in the SQL "radacct" table before die. $ gdb /opt/sbin/radiusd ./core.1100 GNU gdb Red Hat Linux (6.1post-1.20040607.62rh) Copyright 2004 Free Software Foundation, Inc. GDB is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Type "show copying" to see the conditions. There is absolutely no warranty for GDB. Type "show warranty" for details. This GDB was configured as "ppc64-redhat-linux-gnu"...Using host libthread_db library "/lib64/tls/libthread_db.so.1". Core was generated by `/opt/sbin/radiusd -xx'. Program terminated with signal 6, Aborted. Reading symbols from /lib/libnsl.so.1...done. Loaded symbols for /lib/libnsl.so.1 Reading symbols from /lib/libresolv.so.2...done. Loaded symbols for /lib/libresolv.so.2 Reading symbols from /lib/tls/libpthread.so.0...done. Loaded symbols for /lib/tls/libpthread.so.0 Reading symbols from /opt/lib/libradius-1.1.0-pre0.so...done. Loaded symbols for /opt/lib/libradius-1.1.0-pre0.so Reading symbols from /usr/lib/libsnmp.so.5...done. Loaded symbols for /usr/lib/libsnmp.so.5 Reading symbols from /usr/lib/libltdl.so.3...done. Loaded symbols for /usr/lib/libltdl.so.3 Reading symbols from /lib/libssl.so.4...done. Loaded symbols for /lib/libssl.so.4 Reading symbols from /lib/libcrypto.so.4...done. Loaded symbols for /lib/libcrypto.so.4 Reading symbols from /lib/libcrypt.so.1...done. Loaded symbols for /lib/libcrypt.so.1 Reading symbols from /lib/libdl.so.2...done. Loaded symbols for /lib/libdl.so.2 Reading symbols from /lib/tls/libc.so.6...done. Loaded symbols for /lib/tls/libc.so.6 Reading symbols from /lib/ld.so.1...done. Loaded symbols for /lib/ld.so.1 Reading symbols from /usr/lib/libgssapi_krb5.so.2...done. Loaded symbols for /usr/lib/libgssapi_krb5.so.2 Reading symbols from /usr/lib/libkrb5.so.3...done. Loaded symbols for /usr/lib/libkrb5.so.3 Reading symbols from /lib/libcom_err.so.2...done. Loaded symbols for /lib/libcom_err.so.2 Reading symbols from /usr/lib/libk5crypto.so.3...done. Loaded symbols for /usr/lib/libk5crypto.so.3 Reading symbols from /usr/lib/libz.so.1...done. Loaded symbols for /usr/lib/libz.so.1 Reading symbols from /lib/libnss_files.so.2...done. Loaded symbols for /lib/libnss_files.so.2 Reading symbols from /opt/lib/rlm_preprocess-1.1.0-pre0.so...done. Loaded symbols for /opt/lib/rlm_preprocess-1.1.0-pre0.so Reading symbols from /opt/lib/rlm_detail-1.1.0-pre0.so...done. Loaded symbols for /opt/lib/rlm_detail-1.1.0-pre0.so Reading symbols from /opt/lib/rlm_sql-1.1.0-pre0.so...done. Loaded symbols for /opt/lib/rlm_sql-1.1.0-pre0.so Reading symbols from /opt/lib/rlm_sql_mysql-1.1.0-pre0.so...done. Loaded symbols for /opt/lib/rlm_sql_mysql-1.1.0-pre0.so Reading symbols from /usr/lib/mysql/libmysqlclient.so.14...done. Loaded symbols for /usr/lib/mysql/libmysqlclient.so.14 Reading symbols from /lib/tls/libm.so.6...done. Loaded symbols for /lib/tls/libm.so.6 Reading symbols from /opt/lib/rlm_acct_unique-1.1.0-pre0.so...done. Loaded symbols for /opt/lib/rlm_acct_unique-1.1.0-pre0.so Reading symbols from /opt/lib/rlm_radutmp-1.1.0-pre0.so...done. Loaded symbols for /opt/lib/rlm_radutmp-1.1.0-pre0.so #0 0x0fe90d1c in raise () from /lib/tls/libc.so.6 (gdb) bt #0 0x0fe90d1c in raise () from /lib/tls/libc.so.6 #1 0x0fe927a0 in abort () from /lib/tls/libc.so.6 #2 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #3 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #4 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #5 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #6 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #7 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #8 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #9 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #10 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #11 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #12 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #13 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #14 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #15 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #16 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #17 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #18 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #19 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #20 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #21 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #22 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 #23 0x0fec7674 in __libc_message () from /lib/tls/libc.so.6 Previous frame inner to this frame (corrupt stack?) -- -=AV=-
"Alexander Voropay" <alec@artcoms.ru> wrote:
As far as I understand, SQL module segfaults when SQL connection pool is over. Seems, pooling mechanism is bogus.
Use gdb, or submit patches. No one else has seen this problem, so it's a little difficult for others to fix it. Or, use the "rlm_sql_log" module from CVS. It logs the SQL queries to a file, which should be able to handle any load. A Perl script then picks them up out of the file, and writes them to SQL.
Is there any way to avoid insertion of this empty records ?
Don't insert them. You should be able to configure the server to not call the SQL module for empty records. Alan DeKok.
participants (3)
-
Alan DeKok -
Alexander Voropay -
Nicolas Baradakis