over 30 radiusd processes - more information

[Ivan Kalik]

> I've continued to try an investigate the root cause of this, and the last
> run behaved slightly differently - the parent process seems to have
> terminated, and there are more messages in the radius log.
>
> There were four (4) hung processes left over.
>
> I have attached the radius.log file below, as well as gdb sessions for the
> hung processes showing the results of the gd 'bt' and 'list' commands.
>
> It looks like Alan's initial idea that the hung processes are a result of
> running the acctstop.sh process are correct.  I've tried looking at the
> code
> to see if anything 'leapt out' at me, but the logic is quite clever, and
> dissecting it from the middle is quite a challenge.
>
> I am hoping that the gdb output might prove helpful to someone already
> familiar with the logic flow.
>
> It seems I can reproduce this issue within 24 hours, so if there is any
> other information I could gather, please left me know.
>
> Thanks,
> -craig
>
> radiusd.log
>
> Fri Oct 16 11:15:56 2009 : Info: Exiting normally.
> Fri Oct 16 11:16:22 2009 : Info: rlm_sql (sql): Driver rlm_sql_mysql
> (module
> rlm_sql_mysql) loaded and linked
> Fri Oct 16 11:16:22 2009 : Info: rlm_sql (sql): Attempting to connect to
> radiusd at localhost:/radius
> Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #0
> Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #1
> Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #2
> Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #3
> Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #4
> Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server inner-tunnel
> Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server
> copy-acct-to-home-server
> Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server
> copy-acct-to-radius-c
> Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server <default>
> Fri Oct 16 11:16:22 2009 : Info: Ready to process requests.
> Fri Oct 16 17:29:12 2009 : Error: [sql] stop packet with zero session
> length. [user 'user35 at realm4TL', nas '192.168.1.101']
> Sat Oct 17 02:00:18 2009 : Error: [sql] stop packet with zero session
> length. [user 'user22 at realm1', nas '192.168.1.101']
> Sat Oct 17 02:00:18 2009 : Error: [sql] stop packet with zero session
> length. [user 'user17 at realm1', nas '192.168.1.101']
etc.

/*
 * If stop but zero session length AND no previous
 * session found, drop it as in invalid packet
 * This is to fix CISCO's aaa from filling our
 * table with bogus crap
 */

Your NAS is broken. Fix it so it sends proper accounting packets.

Ivan Kalik
Kalik Informatika ISP