Re: Strange error log: NAS restarted

2010-01-06 Thread Dinh Pham Cong 
Thanks Alan,

I have just been confirmed with our telco that one of their GGSN devices
would be out of service soon so they blocked the packets coming from our
Radius server. Therefore, while they continue to send accounting packets to
us, they refuse to receive responses.

Regards,

Dinh

On Wed, Jan 6, 2010 at 3:38 PM, Alan DeKok wrote:

> Dinh Pham Cong wrote:
> > Thanks,
> >
> > I already created a file named radutmp but I still see no message there.
> > The message "Info: rlm_radutmp: NAS ggsn-add1 restarted (Accounting-On
> > packet seen)" appears again and again. Does it mean that NAS server
> > restarted continuously or it is just rlm_radutmp behavior when its
> > message can not be logged?
>
>   It means that the server didn't respond to the NAS, so the NAS is
> re-transmitting the same packet.
>
>  Alan DeKok.
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
>
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: Strange error log: NAS restarted

2010-01-05 Thread Dinh Pham Cong 
Thanks,

I already created a file named radutmp but I still see no message there. The
message "Info: rlm_radutmp: NAS ggsn-add1 restarted (Accounting-On packet
seen)" appears again and again. Does it mean that NAS server restarted
continuously or it is just rlm_radutmp behavior when its message can not be
logged?

Regards,

Dinh

2010/1/6 EasyHorpak.com 

>  Dinh Pham Cong wrote:
>
> Hi all,
>
> I noticed that radius.log is filled with a lot of messages as follows:
>
> Wed Jan  6 10:54:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:54:35 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:55:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:55:35 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:55:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:55:35 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:56:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:56:35 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:56:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:56:36 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:57:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:57:35 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:57:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:57:36 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:58:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:58:35 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:58:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:58:36 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:58:56 2010 : Error: [sql] stop packet with zero session
> length. [ip '10.136.0.13', nas '10.0.40.154']
> Wed Jan  6 10:59:02 2010 : Error: [sql] stop packet with zero session
> length. [ip '10.136.0.13', nas '10.0.40.154']
> Wed Jan  6 10:59:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:59:35 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 10:59:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 10:59:36 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 11:00:05 2010 : Error: [sql] stop packet with zero session
> length. [ip '10.136.0.5', nas '10.0.40.153']
> Wed Jan  6 11:00:11 2010 : Error: [sql] stop packet with zero session
> length. [ip '10.136.0.5', nas '10.0.40.153']
> Wed Jan  6 11:00:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 11:00:35 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
> Wed Jan  6 11:00:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
> (Accounting-On packet seen)
> Wed Jan  6 11:00:36 2010 : Error: rlm_radutmp: Error accessing file
> /srv/radius/var/log/radius/radutmp: No such file or directory
>
> The message "Info: rlm_radutmp: NAS ggsn-add1 restarted (Accounting-On
> packet seen)" has been repeating for several hours
>
> Could you kindly point me the right direction?
>
> Regards,
>
> Dinh
>
> --
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>
>  you may config wrong path
>
>
> /srv/radius/var/log/radius/radutmp
>
> by normal it should be /var/log/radius/radutmp
>
>
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Strange error log: NAS restarted

2010-01-05 Thread Dinh Pham Cong 
Hi all,

I noticed that radius.log is filled with a lot of messages as follows:

Wed Jan  6 10:54:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:54:35 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:55:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:55:35 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:55:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:55:35 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:56:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:56:35 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:56:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:56:36 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:57:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:57:35 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:57:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:57:36 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:58:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:58:35 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:58:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:58:36 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:58:56 2010 : Error: [sql] stop packet with zero session
length. [ip '10.136.0.13', nas '10.0.40.154']
Wed Jan  6 10:59:02 2010 : Error: [sql] stop packet with zero session
length. [ip '10.136.0.13', nas '10.0.40.154']
Wed Jan  6 10:59:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:59:35 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 10:59:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 10:59:36 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 11:00:05 2010 : Error: [sql] stop packet with zero session
length. [ip '10.136.0.5', nas '10.0.40.153']
Wed Jan  6 11:00:11 2010 : Error: [sql] stop packet with zero session
length. [ip '10.136.0.5', nas '10.0.40.153']
Wed Jan  6 11:00:35 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 11:00:35 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory
Wed Jan  6 11:00:36 2010 : Info: rlm_radutmp: NAS ggsn-add1 restarted
(Accounting-On packet seen)
Wed Jan  6 11:00:36 2010 : Error: rlm_radutmp: Error accessing file
/srv/radius/var/log/radius/radutmp: No such file or directory

The message "Info: rlm_radutmp: NAS ggsn-add1 restarted (Accounting-On
packet seen)" has been repeating for several hours

Could you kindly point me the right direction?

Regards,

Dinh
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: Radiusd process exited without notice

2010-01-05 Thread Dinh Pham Cong 
Correct me if I am wrong.

As I read from http://www.faqs.org/rfcs/rfc2139.html, when Acct-Session-Time
is zero, user who is associated with such a session has no service:

+ The accounting start packet and stop packet are sent at nearly the same
time. It may be a result of an access denial or user just establishes
network connection and stop it right after that However, if a message
that gives a notice of Acct-Session-Time = 0 is logged, it does mean that
accounting start packet is missing or lost. Or accounting stop packet just
comes first.

Is this kind of packet taken into account in radmin statistics?

Regards,

Dinh

On Wed, Jan 6, 2010 at 2:41 AM, Alan Buxey  wrote:

> Hi,
> > I think these may be valid (more or less) messages containing a
> > Acct-Session-Time = 0
>
> certainly - some NAS kit sends such things.
>
> alan
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
>
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Radiusd process exited without notice

2009-12-20 Thread Dinh Pham Cong 
Hi all,

I noticed that my radiusd process exited silently this morning without any
notice before I must start it manually at Mon Dec 21 10:42:23 2009 as you
can see in the below log messages. Besides, no crash is recorded in
/var/log/messages.

Any recommendation to troubleshoot this problem is appreciated.

Sun Dec 20 21:37:51 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.34.22', nas '10.0.41.137']
Sun Dec 20 21:39:26 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.70.57', nas '10.0.41.138']
Sun Dec 20 22:00:52 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.36.222', nas '10.0.41.138']
Sun Dec 20 22:04:04 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.115.184', nas '10.0.41.138']
Sun Dec 20 22:15:23 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.66.205', nas '10.0.41.138']
Sun Dec 20 22:33:15 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.36.99', nas '10.0.41.138']
Sun Dec 20 22:51:12 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.49.23', nas '10.0.41.137']
Sun Dec 20 23:30:07 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.108.156', nas '10.0.41.138']
Sun Dec 20 23:35:32 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.64.196', nas '10.0.41.137']
Mon Dec 21 00:35:44 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.52.91', nas '10.0.41.137']
Mon Dec 21 01:44:33 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.16.35', nas '10.0.41.138']
Mon Dec 21 03:28:49 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.8.63', nas '10.0.41.138']
Mon Dec 21 03:55:37 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.48.182', nas '10.0.41.137']
Mon Dec 21 04:27:51 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.33.43', nas '10.0.41.137']
Mon Dec 21 05:45:55 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.32.232', nas '10.0.41.138']
Mon Dec 21 05:55:46 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.69.204', nas '10.0.41.138']
Mon Dec 21 06:51:41 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.26.247', nas '10.0.41.137']
Mon Dec 21 06:56:50 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.24.21', nas '10.0.41.138']
Mon Dec 21 08:27:47 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.8.85', nas '10.0.41.138']
Mon Dec 21 08:36:01 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.138.176', nas '10.0.41.137']
Mon Dec 21 08:42:41 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.68.198', nas '10.0.41.137']
Mon Dec 21 08:46:53 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.26.233', nas '10.0.41.137']
Mon Dec 21 09:07:01 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.110.49', nas '10.0.41.137']
Mon Dec 21 09:14:04 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.35.224', nas '10.0.41.137']
Mon Dec 21 09:36:55 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.65.233', nas '10.0.41.138']
Mon Dec 21 09:41:02 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.39.177', nas '10.0.41.138']
Mon Dec 21 10:04:22 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.12.71', nas '10.0.41.137']
Mon Dec 21 10:04:23 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.52.107', nas '10.0.41.137']
Mon Dec 21 10:04:23 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.82.155', nas '10.0.41.137']
Mon Dec 21 10:04:24 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.14.240', nas '10.0.41.137']
Mon Dec 21 10:04:26 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.31.29', nas '10.0.41.137']
Mon Dec 21 10:04:26 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.24.30', nas '10.0.41.137']
Mon Dec 21 10:04:26 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.25.245', nas '10.0.41.138']
Mon Dec 21 10:04:26 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.25.49', nas '10.0.41.138']
Mon Dec 21 10:04:27 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.35.84', nas '10.0.41.137']
Mon Dec 21 10:04:27 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.51.7', nas '10.0.41.138']
Mon Dec 21 10:04:27 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.8.155', nas '10.0.41.137']
Mon Dec 21 10:04:27 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.39.232', nas '10.0.41.138']
Mon Dec 21 10:04:27 2009 : Info: rlm_sql (sql): There are no DB handles to
use! skipped 0, tried to connect 0
Mon Dec 21 10:04:27 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.37.42', nas '10.0.41.

Dropped packet and Radius stats

2009-12-18 Thread Dinh Pham Cong 
Hi all,

My Radius server has received a lot of invalid packets. Those packets are
dropped but the stats shows that no packet is dropped. Is it a bug?


Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.137 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.137 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.137 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.137 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.137 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: [sql] stop packet with zero session
length. [ip '10.160.15.191', nas '10.0.41.137']
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.137 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.137 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.
Fri Dec 18 17:54:30 2009 : Error: Received Accounting-Request packet from
10.0.41.138 with invalid signature!  (Shared secret is incorrect.) Dropping
packet without response.

[r...@radiusd2 mysql]# ./radmin -e "stats client acct"
requests939800
responses   690622
dup 0
invalid 0
malformed   0
bad_signature   0
dropped 0
unknown_types   0
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Warning "stop packet with zero session length" and the difference between number of Radius requests and responses

2009-12-18 Thread Dinh Pham Cong 
Hi all,

I set up a FreeRadius server to receive accounting start/stop packet from
GGSN. Then FreeRadius will save the information into MySQL database.
However, I see that there is a different between the number of received
packets and the Radius response to GGSN

[r...@radiusd2 sbin]# ./radmin -e "stats client acct"
requests422959
responses   412155
dup 0
invalid 0
malformed   0
bad_signature   0
dropped 0
unknown_types   0

I understand that if GGSN sends an accounting start packet to Radius, it
should make a corespondent response or GGSN will resend the packet. So I
don't know why there is such a difference. Meanwhile, radius.log is filled
with a lot of messages like those:

Fri Dec 18 16:55:17 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.55.236', nas '10.0.40.145']
Fri Dec 18 16:55:17 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.61.79', nas '10.0.40.145']
Fri Dec 18 16:55:19 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.67.5', nas '10.0.40.146']
Fri Dec 18 16:55:19 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.93.207', nas '10.0.40.145']
Fri Dec 18 16:55:20 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.136.106', nas '10.0.40.145']
Fri Dec 18 16:55:20 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.56.0', nas '10.0.40.145']
Fri Dec 18 16:55:20 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.81.206', nas '10.0.40.146']
Fri Dec 18 16:55:22 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.35.166', nas '10.0.40.146']
Fri Dec 18 16:55:23 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.55.236', nas '10.0.40.145']
Fri Dec 18 16:55:23 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.61.79', nas '10.0.40.145']
Fri Dec 18 16:55:24 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.51.252', nas '10.0.40.145']
Fri Dec 18 16:55:25 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.93.207', nas '10.0.40.145']
Fri Dec 18 16:55:25 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.67.5', nas '10.0.40.146']
Fri Dec 18 16:55:26 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.56.0', nas '10.0.40.145']
Fri Dec 18 16:55:28 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.35.166', nas '10.0.40.146']
Fri Dec 18 16:55:30 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.51.252', nas '10.0.40.145']
Fri Dec 18 16:55:31 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.93.207', nas '10.0.40.145']
Fri Dec 18 16:55:32 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.49.191', nas '10.0.40.146']
Fri Dec 18 16:55:32 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.56.0', nas '10.0.40.145']
Fri Dec 18 16:55:32 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.75.195', nas '10.0.40.145']
Fri Dec 18 16:55:35 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.91.184', nas '10.0.40.146']
Fri Dec 18 16:55:36 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.113.243', nas '10.0.40.146']
Fri Dec 18 16:55:36 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.95.3', nas '10.0.40.145']
Fri Dec 18 16:55:37 2009 : Error: [sql] stop packet with zero session
length. [ip '117.5.51.252', nas '10.0.40.145']


Any suggestion would be appreciated.

Regards,


Dinh
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

FreeRadius 2.1.7 crashes

2009-12-16 Thread Dinh Pham Cong 
Hi all,

I had run FreeRadius 2.1.7 in gdb and got this core dump

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x2aac59f0e940 (LWP 23452)]
0x00309a85306b in ?? () from /usr/lib64/mysql/libmysqlclient_r.so.15
(gdb) bt
#0  0x00309a85306b in ?? () from /usr/lib64/mysql/libmysqlclient_r.so.15
#1  0x00309a8533e9 in my_net_read () from
/usr/lib64/mysql/libmysqlclient_r.so.15
#2  0x00309a84cd1f in cli_safe_read () from
/usr/lib64/mysql/libmysqlclient_r.so.15
#3  0x00309a84e673 in mysql_real_connect () from
/usr/lib64/mysql/libmysqlclient_r.so.15
#4  0x2ae5ed7663fb in sql_init_socket (sqlsocket=0x4428d90,
config=0x42d81f0) at sql_mysql.c:89
#5  0x2ae5ed561e42 in connect_single_socket (sqlsocket=0x4428d90,
inst=0x42d8180) at sql.c:56
#6  0x2ae5ed562049 in rlm_sql_query (sqlsocket=0x4428d90,
inst=0x42d8180,
query=0x2aac59f0c2f0 " DELETE FROM  radacct", ' ' , "WHERE acctuniqueid =  'bffb320ed0f4f462'") at sql.c:523
#7  0x2ae5ed560987 in rlm_sql_accounting (instance=0x42d8180,
request=0x2aabb4033a20) at rlm_sql.c:1337
#8  0x00419da9 in modcall (component=3, c=,
request=0x2aabb4033a20) at modcall.c:292
#9  0x0041733d in indexed_modcall (comp=3, idx=0,
request=0x2aabb4033a20) at modules.c:691
#10 0x00407f37 in rad_accounting (request=0x2aabb4033a20) at
acct.c:93
#11 0x00423ad1 in radius_handle_request (request=0x2aabb4033a20,
fun=0x407ea0 ) at event.c:3693
#12 0x0041cc83 in request_handler_thread (arg=)
at threads.c:492
#13 0x003e10206367 in start_thread () from /lib64/libpthread.so.0
#14 0x003e0f6d2f7d in clone () from /lib64/libc.so.6

Do you think that it is MySQL client library bug? How can I do now?

Regards,

Dinh
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: Help on debugging Freeradius

2009-12-16 Thread Dinh Pham Cong 
Hi,

I can view thread information of radiusd process by attaching its process ID
into gdb as follows

gdb -q - 19201

After that

(gdb) bt
#0  0x0037ed8cc4c2 in select () from /lib64/libc.so.6
#1  0x2aefb56dd817 in fr_event_loop (el=0x72848a0) at event.c:378
#2  0x0041a877 in main (argc=, argv=0x3ec) at
radiusd.c:398

Does it have any implication on Radius crashes that happened before?

Regards,

Dinh


On Wed, Dec 16, 2009 at 4:13 PM, Dinh Pham Cong  wrote:

> Hi all,
>
> My Freeradiusd 2.1.7 got crashed a lot of times today so I decided to run
> radiusd in gdb
>
> /etc/init.d/radiusd stop
> # gdb /usr/local/sbin/radiusd
> GNU gdb Fedora (6.8-27.el5)
> Copyright (C) 2008 Free Software Foundation, Inc.
> License GPLv3+: GNU GPL version 3 or later <
> http://gnu.org/licenses/gpl.html>
> This is free software: you are free to change and redistribute it.
> There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
> and "show warranty" for details.
> This GDB was configured as "x86_64-redhat-linux-gnu"...
> (gdb) set logging file gdb-radiusd.log
> (gdb) set logging on
> Copying output to gdb-radiusd.log.
> (gdb) run
> Starting program: /usr/local/sbin/radiusd
> [Thread debugging using libthread_db enabled]
> [New Thread 0x2b34e4b7fe10 (LWP 27411)]
> [New Thread 0x41c8b940 (LWP 27414)]
> [Thread 0x41c8b940 (LWP 27414) exited]
> Detaching after fork from child process 27416.
>
> Program exited normally.
> (gdb)
> (gdb)
> (gdb)
> (gdb) info threads
> No registers.
> (gdb) thread apply all bt full
> No registers.
> (gdb) info threads
> No registers.
> (gdb) bt
> No stack.
>
> I already re-compiled FreeRadius with -enable-developer and set
> allows_core_dump = yes in the configuration file. But I don't know why I can
> not get the back trace when the segmentation fault happens
>
> Dec 16 13:10:01 MobileTV-6 kernel: radiusd[1639]: segfault at
> 00c8 rip 003daee5306b rsp 2aabfeef5180 error 4
> Dec 16 15:14:06 MobileTV-6 kernel: radiusd[5486]: segfault at
> 00c8 rip 003daee5306b rsp 2aab4b7d6180 error 4
> Dec 16 15:14:06 MobileTV-6 kernel: radiusd[11466]: segfault at
> 00c8 rip 003daee5306b rsp 2aaf2c785180 error 4
> Dec 16 15:27:16 MobileTV-6 kernel: radiusd[16567]: segfault at
> 0098 rip 003daee530f1 rsp 2aacc4820180 error 4
> Dec 16 15:27:16 MobileTV-6 kernel: radiusd[24913]: segfault at
> 00c8 rip 003daee5306b rsp 2aae33d64180 error 4
> Dec 16 15:31:42 MobileTV-6 kernel: radiusd[26558]: segfault at
> 0002 rip 003daee51b35 rsp 2aab453bb150 error 6
> Dec 16 15:31:42 MobileTV-6 kernel: radiusd[27347]: segfault at
> 0002 rip 003daee51b35 rsp 2aad3da66150 error 6
> Dec 16 15:31:42 MobileTV-6 kernel: radiusd[27322]: segfault at
> 0002 rip 003daee51b35 rsp 2aad2e04d150 error 6
> Dec 16 15:31:42 MobileTV-6 kernel: radiusd[26487]: segfault at
> 0002 rip 003daee51b35 rsp 2aab18d74150 error 6
> Dec 16 15:32:21 MobileTV-6 kernel: radiusd[30883]: segfault at
> 0002 rip 003daee51b35 rsp 2aabc3896150 error 6
> Dec 16 15:32:21 MobileTV-6 kernel: radiusd[31407]: segfault at
> 0002 rip 003daee51b35 rsp 2aad1742f150 error 6
> Dec 16 15:32:21 MobileTV-6 kernel: radiusd[31156]: segfault at
> 0002 rip 003daee51b35 rsp 2aac6e3a7150 error 6
> Dec 16 15:32:21 MobileTV-6 kernel: radiusd[31460]: segfault at
> 0002 rip 003daee51b35 rsp 2aad38665150 error 6
> Dec 16 15:35:53 MobileTV-6 kernel: radiusd[32595]: segfault at
> 00c8 rip 003daee5306b rsp 2aab7740b180 error 4
> Dec 16 15:43:55 MobileTV-6 kernel: radiusd[4822]: segfault at
> 00c8 rip 003daee5306b rsp 2aac53f7c780 error 4
> Dec 16 15:44:07 MobileTV-6 kernel: radiusd[14485]: segfault at
> 00c8 rip 003daee5306b rsp 2aaecf241180 error 4
> Dec 16 15:44:20 MobileTV-6 kernel: radiusd[15346]: segfault at
> 00c8 rip 003daee5306b rsp 2aab2ff99180 error 4
> Dec 16 15:44:33 MobileTV-6 kernel: radiusd[18676]: segfault at
> 00c8 rip 003daee5306b rsp 2aae233e5180 error 4
> Dec 16 15:57:44 MobileTV-6 kernel: radiusd[27191]: segfault at
> 00c8 rip 003daee5306b rsp 2aae381a2180 error 4
> Dec 16 15:57:56 MobileTV-6 kernel: radiusd[31469]: segfault at
> 00c8 rip 003daee5306b rsp 2aaacbef9180 error 4
>
>
> uname -a
> Linux MobileTV-6 2.6.18-128.el5 #1 SMP Wed Jan 21 10:41:14 EST 2009 x86_64
> x86_64 x86_64 GNU/Linux
>
> free -m
>  total   used   fr

Help on debugging Freeradius

2009-12-16 Thread Dinh Pham Cong 
Hi all,

My Freeradiusd 2.1.7 got crashed a lot of times today so I decided to run
radiusd in gdb

/etc/init.d/radiusd stop
# gdb /usr/local/sbin/radiusd
GNU gdb Fedora (6.8-27.el5)
Copyright (C) 2008 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later 
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu"...
(gdb) set logging file gdb-radiusd.log
(gdb) set logging on
Copying output to gdb-radiusd.log.
(gdb) run
Starting program: /usr/local/sbin/radiusd
[Thread debugging using libthread_db enabled]
[New Thread 0x2b34e4b7fe10 (LWP 27411)]
[New Thread 0x41c8b940 (LWP 27414)]
[Thread 0x41c8b940 (LWP 27414) exited]
Detaching after fork from child process 27416.

Program exited normally.
(gdb)
(gdb)
(gdb)
(gdb) info threads
No registers.
(gdb) thread apply all bt full
No registers.
(gdb) info threads
No registers.
(gdb) bt
No stack.

I already re-compiled FreeRadius with -enable-developer and set
allows_core_dump = yes in the configuration file. But I don't know why I can
not get the back trace when the segmentation fault happens

Dec 16 13:10:01 MobileTV-6 kernel: radiusd[1639]: segfault at
00c8 rip 003daee5306b rsp 2aabfeef5180 error 4
Dec 16 15:14:06 MobileTV-6 kernel: radiusd[5486]: segfault at
00c8 rip 003daee5306b rsp 2aab4b7d6180 error 4
Dec 16 15:14:06 MobileTV-6 kernel: radiusd[11466]: segfault at
00c8 rip 003daee5306b rsp 2aaf2c785180 error 4
Dec 16 15:27:16 MobileTV-6 kernel: radiusd[16567]: segfault at
0098 rip 003daee530f1 rsp 2aacc4820180 error 4
Dec 16 15:27:16 MobileTV-6 kernel: radiusd[24913]: segfault at
00c8 rip 003daee5306b rsp 2aae33d64180 error 4
Dec 16 15:31:42 MobileTV-6 kernel: radiusd[26558]: segfault at
0002 rip 003daee51b35 rsp 2aab453bb150 error 6
Dec 16 15:31:42 MobileTV-6 kernel: radiusd[27347]: segfault at
0002 rip 003daee51b35 rsp 2aad3da66150 error 6
Dec 16 15:31:42 MobileTV-6 kernel: radiusd[27322]: segfault at
0002 rip 003daee51b35 rsp 2aad2e04d150 error 6
Dec 16 15:31:42 MobileTV-6 kernel: radiusd[26487]: segfault at
0002 rip 003daee51b35 rsp 2aab18d74150 error 6
Dec 16 15:32:21 MobileTV-6 kernel: radiusd[30883]: segfault at
0002 rip 003daee51b35 rsp 2aabc3896150 error 6
Dec 16 15:32:21 MobileTV-6 kernel: radiusd[31407]: segfault at
0002 rip 003daee51b35 rsp 2aad1742f150 error 6
Dec 16 15:32:21 MobileTV-6 kernel: radiusd[31156]: segfault at
0002 rip 003daee51b35 rsp 2aac6e3a7150 error 6
Dec 16 15:32:21 MobileTV-6 kernel: radiusd[31460]: segfault at
0002 rip 003daee51b35 rsp 2aad38665150 error 6
Dec 16 15:35:53 MobileTV-6 kernel: radiusd[32595]: segfault at
00c8 rip 003daee5306b rsp 2aab7740b180 error 4
Dec 16 15:43:55 MobileTV-6 kernel: radiusd[4822]: segfault at
00c8 rip 003daee5306b rsp 2aac53f7c780 error 4
Dec 16 15:44:07 MobileTV-6 kernel: radiusd[14485]: segfault at
00c8 rip 003daee5306b rsp 2aaecf241180 error 4
Dec 16 15:44:20 MobileTV-6 kernel: radiusd[15346]: segfault at
00c8 rip 003daee5306b rsp 2aab2ff99180 error 4
Dec 16 15:44:33 MobileTV-6 kernel: radiusd[18676]: segfault at
00c8 rip 003daee5306b rsp 2aae233e5180 error 4
Dec 16 15:57:44 MobileTV-6 kernel: radiusd[27191]: segfault at
00c8 rip 003daee5306b rsp 2aae381a2180 error 4
Dec 16 15:57:56 MobileTV-6 kernel: radiusd[31469]: segfault at
00c8 rip 003daee5306b rsp 2aaacbef9180 error 4


uname -a
Linux MobileTV-6 2.6.18-128.el5 #1 SMP Wed Jan 21 10:41:14 EST 2009 x86_64
x86_64 x86_64 GNU/Linux

free -m
 total   used   free sharedbuffers cached
Mem: 16044   4825  11219  0158   3332
-/+ buffers/cache:   1334  14710
Swap: 2047  0   2047

ulimit -a
core file size  (blocks, -c) 0
data seg size   (kbytes, -d) unlimited
scheduling priority (-e) 0
file size   (blocks, -f) unlimited
pending signals (-i) 137216
max locked memory   (kbytes, -l) 32
max memory size (kbytes, -m) unlimited
open files  (-n) 10
pipe size(512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority  (-r) 0
stack size  (kbytes, -s) 10240
cpu time   (seconds, -t) unlimited
max user processes  (-u) 137216
virtual memory  (kbytes, -v) unlimited
file locks  (-x) unlimited

Could you kindly point me the right direction?

Thanks,

Dinh
-
List in

Re: FreeRadius 2.7 virtual memory

2009-12-16 Thread Dinh Pham Cong 
Hi Alan

The version I am using is 2.1.7

Regards,

Dinh

On Wed, Dec 16, 2009 at 3:24 PM, Alan DeKok wrote:

> Dinh Pham Cong wrote:
> > Hi all,
> >
> > My Radiusd seems to take a lot of virtual memory. Here is what shows up
> > in "top" command
> >
> >  4799 mysql 15   0 2606m 697m 3616 S 50.6  4.3  31:46.85 mysqld
> > 14959 root  15   0 10.1g  46m 1456 S 11.1  0.3   1:24.67 radiusd
> >
> > Do you think that I have kind of abnomal operations here?
>
>   Yes.  Could you say which version of the server you're running?
>
>  Alan DeKok.
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
>
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

FreeRadius 2.7 virtual memory

2009-12-15 Thread Dinh Pham Cong 
Hi all,

My Radiusd seems to take a lot of virtual memory. Here is what shows up in
"top" command

 4799 mysql 15   0 2606m 697m 3616 S 50.6  4.3  31:46.85 mysqld
14959 root  15   0 10.1g  46m 1456 S 11.1  0.3   1:24.67 radiusd

Do you think that I have kind of abnomal operations here?

Regards,

Dinh
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: FreeRadius crashed on accounting load tests with 1000 concurrent clients

2009-11-10 Thread Dinh Pham Cong 
Hi Michael,

Yes I have enabled MySQL slow query log for all queries that take more than
1s for execution. I have found 2 slow queries only (INSERT) in one server
and no slow query on the other. Because I installed MySQL using a rpm
package so I can not patch it with microslow patch to enable logging queries
that takes less than a second (e.x 0.5 second).

Thanks,

Dinh

On Wed, Nov 11, 2009 at 12:22 AM, Michael da Silva Pereira <
mich...@tradepage.co.za> wrote:

> Hi Dinh,
>
> max_request_time is 10 seconds, have you switched on mysql slow query /
> non-index lookups logging ? (in my.cnf '#log_slow_queries
> = /var/log/mysql/mysql-slow.log' ).
> If the log file has nothing in it during the testing great, then MySQL
> is happy. If you have queries taking longer than '#long_query_time'
> there might be a problem.
>
> Regards,
> Michael
>
>
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: FreeRadius crashed on accounting load tests with 1000 concurrent clients

2009-11-10 Thread Dinh Pham Cong 
Hi Alan,

On Tue, Nov 10, 2009 at 11:25 PM, Alan DeKok wrote:

>
> But if you follow the instructions in doc/bugs, you will be able to
> give us the data we need to FIX the crash.
>
>
Thanks Alan. I am reviewing my system to see if there is any wrong in our
system settings that can cause FreeRadius crashed under high load. If I can
not find something wrong caused by us, I will fill a bug report. So far,
nothing is found.

Thanks

Dinh
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: FreeRadius crashed on accounting load tests with 1000 concurrent clients

2009-11-10 Thread Dinh Pham Cong 
Hi Alan,

I have attached a graph created by Munin that shows how MySQL works under
FreeRadius load test

http://img4.imageshack.us/img4/7204/mysqlqueriesday.png

This test was conducted last night. I used 2 16-core Dell servers,
FastEthernet 100Mb to run 2 test clients to test 2 Radius servers. Each
client created 100 concurrent threads to simulate 100 concurrent users and
send 10 000 000 start request and 10 000 000 stop each thread. Radius server
and MySQL are installed in a 16-core Dell server too. I expect that the test
can take several hours in the night. At some point of times in the very
early this morning, Munin found that there was very high load in our MySQL
server: 11 000 INSERT query/s and 11 000 DELETE query/s. It was because one
of Radius server crashed and all the traffic was forwarded to the rest by
the load balancer.

It means that MySQL is not slow. There may be a bug in FreeRadius that makes
it impossible to work in very high load environment: thread deadlock or kind
of race condition??? Have someone got into this problem?

Thanks

Dinh

On Tue, Nov 10, 2009 at 10:50 PM, Dinh Pham Cong  wrote:

> Hi Alan,
>
>
> On Tue, Nov 10, 2009 at 8:15 PM, Alan DeKok wrote:
>
>>
>>  FreeRADIUS does a mix of selects, inserts and updates for accounting.
>>  It may be that the DB can only handle 1000 transactions/s with that mix.
>>
>>  See also "sqltrace" config in sql.conf.  You can try the following tests:
>>
>> - start off with a clean (i.e. empty) DB
>> - enable sqltrace
>> - run 10's of 1000's of packets through the server
>> - wipe the DB
>> - use a command-line SQL client to re-play SQL queries from the sqltrace
>> file
>>
>
>
> I have enabled sqltrace and found that for accounting purpose, there was
> only a single query made into MySQL for accounting stop or start: An insert
> for start and a delete for stop. For single INSERT and/or DELETE I have used
> mysqlslap for stress testing and found that MYSQL can handle 6000 - 8700 qps
> for 2000 concurrent clients. Therefore I double that MySQL is not a
> bottleneck. There might be something wrong with FreeRadius that made it not
> scalable when the load is high. When FreeRadius crashed there were only 1200
> - 1400 radiusd threads as Munin recorded it.
>
> The way it crashed is strange too. No fatal error in radius.log. There is a
> single kernel log found in /var/log/messages. Is it stable in 64 bit OS and
> SMP ?
>
> Thanks
>
>
> Dinh
>
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: FreeRadius crashed on accounting load tests with 1000 concurrent clients

2009-11-10 Thread Dinh Pham Cong 
Hi Alan,

On Tue, Nov 10, 2009 at 8:15 PM, Alan DeKok wrote:

>
>  FreeRADIUS does a mix of selects, inserts and updates for accounting.
>  It may be that the DB can only handle 1000 transactions/s with that mix.
>
>  See also "sqltrace" config in sql.conf.  You can try the following tests:
>
> - start off with a clean (i.e. empty) DB
> - enable sqltrace
> - run 10's of 1000's of packets through the server
> - wipe the DB
> - use a command-line SQL client to re-play SQL queries from the sqltrace
> file
>


I have enabled sqltrace and found that for accounting purpose, there was
only a single query made into MySQL for accounting stop or start: An insert
for start and a delete for stop. For single INSERT and/or DELETE I have used
mysqlslap for stress testing and found that MYSQL can handle 6000 - 8700 qps
for 2000 concurrent clients. Therefore I double that MySQL is not a
bottleneck. There might be something wrong with FreeRadius that made it not
scalable when the load is high. When FreeRadius crashed there were only 1200
- 1400 radiusd threads as Munin recorded it.

The way it crashed is strange too. No fatal error in radius.log. There is a
single kernel log found in /var/log/messages. Is it stable in 64 bit OS and
SMP ?

Thanks


Dinh
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Re: FreeRadius crashed on accounting load tests with 1000 concurrent clients

2009-11-10 Thread Dinh Pham Cong 
Hi Alan,

On Tue, Nov 10, 2009 at 5:35 PM, Alan DeKok wrote:

> Dinh Pham Cong wrote:
> > start_servers = 1024
> > max_servers = 3000
> > max_spare_servers = 3000
>
>   That's a little high.
>
>
I saw that when 1000 client was created at the same time and send requests
to Radius server concurrently there were about 2000+ radiusd threads were
created too. I thought that 1000 concurrent client could be translated to
more than 1000 packets/s.

I have done another load tests with smaller concurrent clients: 100, 200,
500. However, Radiusd can not handle more than 1000 request/s (total
requests/total time used to sent all the requests). For example Radiusd can
handle 20 000 request in more than 20 seconds, 40 000 requests in more than
43 seconds.

> My sql.conf
> >
> > # number of sql connections to make to server
> > num_sql_socks = 1000
>
>   Remember: 1000 packets/s does *not* mean 1000 threads or 1000 SQL
> sockets.  The server should be able to do 1000 packets/s with a much
> smaller number of threads && sockets.  i.e. 50/50.
>

I thought that num_sql_socks = 1000 meaned that Radiusd would create a
connection pool of 1000 MySQL connections.


> > I developed a Java client that can create 1000 concurrent threads that
> > connect and send accounting requests (start and stop) to Radius server.
>
>   See also "radperf" (http://networkradius.com/radperf.html).  It can do
> load testing and user login simulations.
>
>
Thanks I will try.


> > However, after sending for 20 or 30 seconds, radius server generated a
> > lot of error messages and crashed
> >
> > Error messages
> >
> > Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from
> > client tester1 port 41442 - ID: 134 due to unfinished request 2436
>
>   This is likely because your SQL database is too slow.
>
>  Have you checked to see if the SQL database can handle 1000 inserts/s?
>
> > Crashed
> >
> > Nov 10 15:55:35 Mobile6 kernel: radiusd[22242]: segfault at
> > 00c8 rip 003daee5306b rsp 2aae5d82a780 error 4
>
>   See doc/bugs for instructions on producing useful crash reports.  We
> can then use these to fix bugs.
>
> > Nov 10 15:57:29 Mobile6 kernel: radiusd[30941]: segfault at
> > 00c8 rip 003daee5306b rsp 2aaee56de180 error 4
> > Nov 10 16:14:36 Mobile kernel: radiusd[10788]: segfault at
> > 00c8 rip 003daee5306b rsp 2aac913de780 error 4
> >
> > What do I need to do to enable FreeRadius server to meet more than 1000
> > accounting request (INSERT AND DELETE) for a second?
>
>   Use a database that can handle 1000 requests/s.
>

I have done separate load tests of INSERT and DELETE on radacct table (using
MEMORY engine) and found that MySQL 5.0 can handle about 6000 - 8700 qps. I
have used mysqlslap to do that.


Thanks

Dinh
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

FreeRadius crashed on accounting load tests with 1000 concurrent clients

2009-11-10 Thread Dinh Pham Cong 
Hi all,

I am using FreeRADIUS Version 2.1.7, CentOS 5.3 64 bit, MySQL 5.0.77 (max
connections 3000) on a 16-core, 16GB RAM server. This is my radiusd.conf

max_request_time = 10
cleanup_delay = 5
max_requests = 5120

start_servers = 1024
max_servers = 3000
max_spare_servers = 3000
max_requests_per_server = 0

My sql.conf

# number of sql connections to make to server
num_sql_socks = 1000

I developed a Java client that can create 1000 concurrent threads that
connect and send accounting requests (start and stop) to Radius server.
However, after sending for 20 or 30 seconds, radius server generated a lot
of error messages and crashed

Error messages

Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 41442 - ID: 134 due to unfinished request 2436
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 38970 - ID: 150 due to unfinished request 2452
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 50783 - ID: 156 due to unfinished request 2458
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 60038 - ID: 162 due to unfinished request 2464
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 59541 - ID: 191 due to unfinished request 2493
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 59858 - ID: 205 due to unfinished request 2507
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 45654 - ID: 220 due to unfinished request 2522
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 59464 - ID: 229 due to unfinished request 2531
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 57658 - ID: 240 due to unfinished request 2542
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 33253 - ID: 71 due to unfinished request 2629
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 54171 - ID: 105 due to unfinished request 2663
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 41039 - ID: 176 due to unfinished request 2734
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 53611 - ID: 199 due to unfinished request 2757
Tue Nov 10 16:14:34 2009 : Error: Discarding duplicate request from client
tester1 port 58608 - ID: 208 due to unfinished request 2766
Tue Nov 10 16:14:36 2009 : Error: Discarding duplicate request from client
tester1 port 33814 - ID: 171 due to unfinished request 4521
Tue Nov 10 16:14:36 2009 : Info: rlm_sql_mysql: Starting connect to MySQL
server for #942
Tue Nov 10 16:14:36 2009 : Error: Discarding duplicate request from client
tester1 port 54081 - ID: 187 due to unfinished request 4537
Tue Nov 10 16:14:36 2009 : Info: rlm_sql_mysql: Starting connect to MySQL
server for #926
Tue Nov 10 16:14:36 2009 : Info: rlm_sql_mysql: Starting connect to MySQL
server for #913
Tue Nov 10 16:14:36 2009 : Error: rlm_sql_mysql: Socket not connected
Tue Nov 10 16:14:36 2009 : Error: rlm_sql_mysql: Socket not connected

Crashed

Nov 10 15:55:35 Mobile6 kernel: radiusd[22242]: segfault at 00c8
rip 003daee5306b rsp 2aae5d82a780 error 4
Nov 10 15:57:29 Mobile6 kernel: radiusd[30941]: segfault at 00c8
rip 003daee5306b rsp 2aaee56de180 error 4
Nov 10 16:14:36 Mobile kernel: radiusd[10788]: segfault at 00c8
rip 003daee5306b rsp 2aac913de780 error 4

What do I need to do to enable FreeRadius server to meet more than 1000
accounting request (INSERT AND DELETE) for a second?

Thanks,

Dinh
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html