Radiusd process exited without notice
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.138'] Mon Dec 21 10:04:27 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.69.183', nas '10.0.41.138'] Mon Dec 21 10:04:27 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.28.249', nas '10.0.41.138'] Mon Dec 21 10:04:27 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.48.247', nas '10.0.41.137'] Mon Dec 21 10:04:28 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Mon Dec 21 10:04:28 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.49.162', nas '10.0.41.137'] Mon Dec 21 10:04:28 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.58.116', nas '10.0.41.137'] Mon Dec 21 10:04:28 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.12.154', nas '10.0.41.138'] Mon Dec 21 10:04:28 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.58.93', nas '10.0.41.138'] Mon Dec 21 10:04:29 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Mon Dec 21 10:04:29 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.34.116', nas '10.0.41.138'] Mon Dec 21 10:04:29 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.110.54', nas '10.0.41.138'] Mon Dec 21 10:04:29 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.27.8', nas '10.0.41.137'] Mon Dec 21 10:04:29 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.105.31', nas '10.0.41.137'] Mon Dec 21 10:04:29 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.0.44', nas '10.0.41.138'] Mon Dec 21 10:04:30 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Mon Dec 21 10:04:30 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.38.21', nas '10.0.41.138'] Mon Dec 21 10:04:30 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.67.0', nas '10.0.41.137'] Mon Dec 21 10:04:31 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.81.41', nas '10.0.41.137'] Mon Dec 21 10:04:31 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.26.205', nas '10.0.41.137'] Mon Dec 21 10:04:31 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.112.205', nas '10.0.41.138'] Mon Dec 21 10:04:31 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.53.225', nas '10.0.41.138'] Mon Dec 21 10:04:31 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.38.170', nas '10.0.41.138'] Mon Dec 21 10:04:32 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.13.15', nas '10.0.41.138'] Mon Dec 21 10:04:32 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.58.157', nas '10.0.41.138'] Mon Dec 21 10:04:32 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.48.134', nas '10.0.41.138'] Mon Dec 21 10:04:32 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.69.19', nas '10.0.41.137'] Mon Dec 21 10:04:32 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.54.41', nas '10.0.41.138'] Mon Dec 21 10:04:32 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.109.253', nas '10.0.41.138'] Mon Dec 21 10:04:32 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.91.90', nas '10.0.41.138'] Mon Dec 21 10:04:32 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.87.73', nas '10.0.41.137'] Mon Dec 21 10:04:32 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.29.105', nas '10.0.41.138'] Mon Dec 21 10:04:33 2009 : Error: Received conflicting packet from client vt-ggsn3-sg port 51682 - ID: 192 due to unfinished request 20099379. Giving up on old request. Mon Dec 21 10:04:33 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.95.191', nas '10.0.41.138'] Mon Dec 21 10:04:33 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.40.108', nas '10.0.41.138'] Mon Dec 21 10:04:33 2009 : Error: [sql] stop packet with zero session length. [ip '10.160.12.148', nas '10.0.41.137'] Mon Dec 21 10:04:33 2009 : Error: Received conflicting packet from client vt-ggsn8-tt port 57385 - ID: 143 due to unfinished request 20099602. Giving up on old request. Mon Dec 21 10:04:33 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #71 Mon Dec 21 10:42:23 2009 : Info: Loaded virtual server inner-tunnel Mon Dec 21 10:42:23 2009 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Mon Dec 21 10:42:23 2009 : Info: rlm_sql (sql): Attempting to connect to radius@localhost:/radius Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #5 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #6 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #7 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #8 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #9 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #10 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #11 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #12 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #13 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #14 Mon Dec 21 10:42:23 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #15 Regards, Dinh
Dinh Pham Cong wrote:
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.
Try using 2.1.8 when it comes out. It looks like an issue that was previously reported, and fixed. Alan DeKok.
I'm running 2.1.8 and while I have some of those messages in my logs (~70), the radiusd process seems totally fine. Cheers, -craig ----- Original Message ----- From: "Alan DeKok" <aland@deployingradius.com> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Monday, December 21, 2009 3:23 AM Subject: Re: Radiusd process exited without notice
Dinh Pham Cong wrote:
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.
Try using 2.1.8 when it comes out. It looks like an issue that was previously reported, and fixed.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4704 (20091220) __________
The message was checked by ESET Smart Security.
__________ Information from ESET Smart Security, version of virus signature database 4744 (20100105) __________ The message was checked by ESET Smart Security. http://www.eset.com
I think these may be valid (more or less) messages containing a Acct-Session-Time = 0 I have no reason to think radiusd is to blame. I'll keep you posted if I learn more. Thanks, -craig ----- Original Message ----- From: "Alan DeKok" <aland@deployingradius.com> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Tuesday, January 05, 2010 10:13 AM Subject: Re: Radiusd process exited without notice
Craig Campbell wrote:
I'm running 2.1.8 and while I have some of those messages in my logs (~70), the radiusd process seems totally fine.
Hmm... that shouldn't be happening. But without a test case, it's hard to track down.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4745 (20100105) __________
The message was checked by ESET Smart Security.
__________ Information from ESET Smart Security, version of virus signature database 4745 (20100105) __________ The message was checked by ESET Smart Security. http://www.eset.com
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 <A.L.M.Buxey@lboro.ac.uk> 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
Dinh Pham Cong wrote:
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 latest RADIUS accounting RFC is 2866. And it contains *no* text about the Acct-Session-Time being zero.
+ The accounting start packet and stop packet are sent at nearly the same time. It may be a result of an access denial
No. If the NAS sends an accounting packet for a session that was rejected, the NAS is broken.
or user just establishes network connection and stop it right after that????
The Acct-Session-Time should be at least 1 second.
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?
radmin doesn't do session accounting. Alan DeKok.
Alan DeKok <aland@deployingradius.com> writes:
Dinh Pham Cong wrote:
or user just establishes network connection and stop it right after that????
The Acct-Session-Time should be at least 1 second.
Why? I can't find any such requirements in RFC 2866. If the session lasts less than .5 seconds then an Acct-Session-Time of 0 makes perfect sense. IMHO. I can agree that the near simultaneous start and stop requests indicates some error, but as suggested by Dinh Pham Cong it may be a user disconnecting immediately after the session is established. That happens. Bjørn
Bjørn Mork wrote:
Alan DeKok <aland@deployingradius.com> writes:
The Acct-Session-Time should be at least 1 second.
Why? I can't find any such requirements in RFC 2866.
The RFC's miss a *lot*. It is permissible for a multi-homed NAS to send an accounting "start" from one IP, "update" from another IP, and "stop" from a third IP. While this is insane, there is equipment that behaves this way.
If the session lasts less than .5 seconds then an Acct-Session-Time of 0 makes perfect sense. IMHO.
Hmm... I still don't like it.
I can agree that the near simultaneous start and stop requests indicates some error, but as suggested by Dinh Pham Cong it may be a user disconnecting immediately after the session is established. That happens.
Yes. Alan DeKok.
Has anyone checked for Acct-Terminate-Cause = User-Error with the packets in question? We are seeing some of the "Info: [sql] stop packet with zero session length." messages logged (but only so far during 1 specific minute of the day) and they ALL have "Acct-Terminate-Cause = User-Error". There is one other packet with Acct-Session-Time = 0 AND Acct-Terminate-Cause = User-Request that does NOT generate the warning. Our current belief is that this is NOT radius related. The troublesome packets do not appear to be causing any harm. (despite the subject, radiusd is NOT exiting and remains healthy and happy (Yeah 2.1.8!! ) I'm just thinking you guys might be chasing a non (radius) issue. Cheers, -craig ----- Original Message ----- From: "Alan DeKok" <aland@deployingradius.com> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Wednesday, January 06, 2010 5:17 AM Subject: Re: Radiusd process exited without notice
Bjørn Mork wrote:
Alan DeKok <aland@deployingradius.com> writes:
The Acct-Session-Time should be at least 1 second.
Why? I can't find any such requirements in RFC 2866.
The RFC's miss a *lot*. It is permissible for a multi-homed NAS to send an accounting "start" from one IP, "update" from another IP, and "stop" from a third IP. While this is insane, there is equipment that behaves this way.
If the session lasts less than .5 seconds then an Acct-Session-Time of 0 makes perfect sense. IMHO.
Hmm... I still don't like it.
I can agree that the near simultaneous start and stop requests indicates some error, but as suggested by Dinh Pham Cong it may be a user disconnecting immediately after the session is established. That happens.
Yes.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4748 (20100106) __________ The message was checked by ESET Smart Security. http://www.eset.com
Just stumbled across a semi-related issue (all accounting modules returned "noop" for a request) which made me wonder if not the recently added documentation for handling noop accounting requests should be promoted to "enabled by default"? It does not make much sense to ignore valid accounting requests just because no module knows how to handle them. It just cause problems as the NAS will retransmit the requests forever. Bjørn
Bjørn Mork wrote:
Just stumbled across a semi-related issue (all accounting modules returned "noop" for a request) which made me wonder if not the recently added documentation for handling noop accounting requests should be promoted to "enabled by default"?
You mean tell the NAS we logged something that wasn't really logged?
It does not make much sense to ignore valid accounting requests just because no module knows how to handle them.
They might be valid... but the whole point of accounting is to *do* something with the packets. I understand your point... but I'm a little wary of ACKing packets when we didn't do anything with them. Alan DeKok.
Alan DeKok <aland@deployingradius.com> writes:
Bjørn Mork wrote:
Just stumbled across a semi-related issue (all accounting modules returned "noop" for a request) which made me wonder if not the recently added documentation for handling noop accounting requests should be promoted to "enabled by default"?
You mean tell the NAS we logged something that wasn't really logged?
The way I see it, we tell the NAS that "we processed the request". Whether the processing involved writing to a log or not is irrelevant. There are accounting requests which do not need to be logged. At least in our network. Some of the NASes insist on sending "Accounting-On" when they're booted. We could discuss the usefulness of this, and we could of course just log the requests, but I see no reason to do so. Not a big matter. I can of course implement this in my setup. Just thought that the issue might bite someone else too. I believe the missing ACKs on NOOP is a change from FreeRADIUS 1.0.x (which we used prior to upgrading to 2.1.8)? Only the NASes bootet after the upgrade were continously resending their reboot accounting requests, so the old RADIUS servers must have ACKed them. And the config is pretty much unchanged.
It does not make much sense to ignore valid accounting requests just because no module knows how to handle them.
They might be valid... but the whole point of accounting is to *do* something with the packets.
I understand your point... but I'm a little wary of ACKing packets when we didn't do anything with them.
Well, looking at them and verifying that they need no further action *is* doing something. Bjørn
participants (5)
-
Alan Buxey -
Alan DeKok -
Bjørn Mork -
Craig Campbell -
Dinh Pham Cong