NAS re-uses the same port and ID
Hi all! I've found, that our NAS-server sometimes (when it restarts and there are many auth. packets comes to the radius-server) re-uses port and ID in a < 1 second period. (information from tcpdump) That causes " conflicting packet from client". I think, that the NAS works wrong (it must wait a little bit more, then 1 sec. to re-use the port+ID), that's why I wont to find some documentation about it for a bug-report. Thanks a lot.
On Wed, Jul 13, 2011 at 1:54 PM, Konstantin Chekushin <koch2@inbox.lv> wrote:
Hi all! I've found, that our NAS-server sometimes (when it restarts and there are many auth. packets comes to the radius-server) re-uses port and ID in a < 1 second period. (information from tcpdump) That causes " conflicting packet from client". I think, that the NAS works wrong (it must wait a little bit more, then 1 sec. to re-use the port+ID), that's why I wont to find some documentation about it for a bug-report. Thanks a lot.
Are you sure the NAS reuse port number? Isn't it a duplicate packet? -- Fajar
Yes, but we just have got the problem, so, the source of the problem may be in other place... I've look through the sniffer file and found, this strange sequence: ... 31:05 access-request (port 65025, id 229) (Authenticator1) 31:10 access-accept (port 65025, id 229) 31:10 access-request (port 65025, id 229) (Authenticator2) 31:14 access-request (port 65025, id 229) (Authenticator2) 31:20 access-request (port 65025, id 229) (Authenticator2) 31:26 access-accept (port 65025, id 229) 31:26 access-request (port 65025, id 229) (Authenticator3) ... I'm not sure, but it seems to me, that some of this requests in radius.log file were marked as duplicated ("Discarding duplicate request from client..."), and some - as a conflicting. ("Received conflicting packet from client...") ... Jul 12 14:31:10 radius1 radiusd[8647]: Discarding duplicate request from client fl2 port 65025 - ID: 229 due to unfinished request 6545 Jul 12 14:31:16 radius1 radiusd[8647]: Discarding duplicate request from client fl2 port 65025 - ID: 229 due to unfinished request 6545 Jul 12 14:31:21 radius1 radiusd[8647]: Received conflicting packet from client fl2 port 65025 - ID: 229 due to unfinished request 6545. Giving up on old request. Jul 12 14:31:22 radius1 radiusd[8647]: Dropping request (2049 is too many): from client fl1 port 65025 - ID: 229 Jul 12 14:31:25 radius1 radiusd[8647]: Discarding duplicate request from client fl2 port 65025 - ID: 229 due to unfinished request 8342 Jul 12 14:31:26 radius1 radiusd[8647]: Dropping request (2049 is too many): from client fl1 port 65025 - ID: 229 ... and so on... Citējot *Fajar A. Nugraha <list@fajar.net> [1]*:
On Wed, Jul 13, 2011 at 1:54 PM, Konstantin Chekushin <koch2@inbox.lv> wrote:
Hi all! I've found, that our NAS-server sometimes (when it restarts and there are many auth. packets comes to the radius-server) re-uses port and ID in a < 1 second period. (information from tcpdump) That causes " conflicting packet from client". I think, that the NAS works wrong (it must wait a little bit more, then 1 sec. to re-use the port+ID), that's why I wont to find some documentation about it for a bug-report. Thanks a lot.
Are you sure the NAS reuse port number? Isn't it a duplicate packet?
-- Fajar
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Links: ------ [1] mailto:list@fajar.net
On Wed, Jul 13, 2011 at 4:14 PM, Konstantin Chekushin <koch2@inbox.lv> wrote:
Yes, but we just have got the problem, so, the source of the problem may be in other place...
There's an analogy I sometime use to explain things like this to my coworkers: "You're driving a new car. Not far from the dealer, the car broke down. You get out, and say 'hey, this car must be broken. Let's get another car'. ... when in fact the problem is simply an empty gas tank"
I've look through the sniffer file and found, this strange sequence:
Let's look at these one by one, shall we. I assume you got the log by using grep or some capture filter to packet sniffer?
... 31:05 access-request (port 65025, id 229) (Authenticator1) 31:10 access-accept (port 65025, id 229)
As Alan said, It's OK to re-use the same port & ID, *if* it's received a response from the RADIUS server. So based on that ...
31:10 access-request (port 65025, id 229) (Authenticator2)
... this request is valid, since the NAS should already got response from radius. However ...
31:14 access-request (port 65025, id 229) (Authenticator2) 31:20 access-request (port 65025, id 229) (Authenticator2)
... those two are duplicate packets. The NAS resent those because the radius server took too long to response. This is the main problem. Now let's get to radius log
Jul 12 14:31:10 radius1 radiusd[8647]: Discarding duplicate request from client fl2 port 65025 - ID: 229 due to unfinished request 6545 Jul 12 14:31:16 radius1 radiusd[8647]: Discarding duplicate request from client fl2 port 65025 - ID: 229 due to unfinished request 6545 Jul 12 14:31:21 radius1 radiusd[8647]: Received conflicting packet from client fl2 port 65025 - ID: 229 due to unfinished request 6545. Giving up on old request.
The times match the duplicate request from your packet sniffer. So bottom line, you need to find out what's causing radius to respond slowly.
Jul 12 14:31:22 radius1 radiusd[8647]: Dropping request (2049 is too many): from client fl1 port 65025 - ID: 229
this one is also an indication that something's wrong with your radius server. It takes too long to respond to a request, thus it's unable to accept new request. Now let's take some time to read a snippet from radiusd.conf: thread pool { ... # You may find that the server is regularly reaching the # 'max_servers' number of threads, and that increasing # 'max_servers' doesn't seem to make much difference. # # If this is the case, then the problem is MOST LIKELY that # your back-end databases are taking too long to respond, and # are preventing the server from responding in a timely manner. # # The solution is NOT do keep increasing the 'max_servers' # value, but instead to fix the underlying cause of the # problem: slow database, or 'hostname_lookups=yes'. # # For more information, see 'max_request_time', above. That should be clear enough. If you're using database backend, then most likely the database is non-optimal (e.g. too many rows, non-optimum queries/index, slow disk, and so on). Often the solution to this problem is to get a dba, cause fixing it would require some skills and knowledge that only a dba has. -- Fajar
Konstantin Chekushin wrote:
Hi all! I've found, that our NAS-server sometimes (when it restarts and there are many auth. packets comes to the radius-server) re-uses port and ID in a < 1 second period. (information from tcpdump) That causes " conflicting packet from client".
It's OK to re-use the same port && ID, *if* it's received a response from the RADIUS server. But if the server says "conflicting packet", then the NAS is broken.
I think, that the NAS works wrong (it must wait a little bit more, then 1 sec. to re-use the port+ID), that's why I wont to find some documentation about it for a bug-report.
The NAS is broken. Alan DeKok.
participants (3)
-
Alan DeKok -
Fajar A. Nugraha -
Konstantin Chekushin