Matthew, please update for the latest 3.0.19 and just go back if you see the same issues on the latest version. — Jorge Pereira
On 8 Jul 2019, at 19:30, Matthew Schumacher <matt.s@aptalaska.net> wrote:
List,
Anyone see this before?
My radius server is plugging away doing it's job, then suddenly I get this:
Sun Jul 7 10:37:47 2019 : Error: Received conflicting packet from client 2.3.23.90 port 53874 - ID: 119 due to unfinished request. Giving up on old request. Sun Jul 7 10:37:50 2019 : Error: Received conflicting packet from client 2.3.23.90 port 53874 - ID: 119 due to unfinished request. Giving up on old request. Sun Jul 7 10:37:53 2019 : Error: Received conflicting packet from client 2.3.22.14 port 39039 - ID: 36 due to unfinished request. Giving up on old request. Sun Jul 7 10:37:56 2019 : Error: Received conflicting packet from client 2.3.22.14 port 39039 - ID: 36 due to unfinished request. Giving up on old request. Sun Jul 7 10:37:56 2019 : Error: Received conflicting packet from client 2.3.22.9 port 46417 - ID: 203 due to unfinished request. Giving up on old request. Sun Jul 7 10:37:57 2019 : Error: Received conflicting packet from client 2.3.23.75 port 57383 - ID: 228 due to unfinished request. Giving up on old request.
Now, I know that's normally because my underlying stack isn't returning fast enough, but in this case I never again see a working radius request until a restart, and my secondary radius server which relies on the same stack works just fine. The primary continued for a few hours recording nothing but logs like above, until it hit the max queue then transitioned to:
Sun Jul 7 12:52:26 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:26 2019 : Error: (18606025) Ignoring duplicate packet from client 2.3.9.250 port 59296 - ID: 120 due to unfinished request in component <core> module <queue> Sun Jul 7 12:52:27 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:28 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:29 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:30 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:30 2019 : Error: (18606051) Ignoring duplicate packet from client 2.3.9.241 port 32851 - ID: 126 due to unfinished request in component <core> module <queue> Sun Jul 7 12:52:30 2019 : Error: (18606052) Ignoring duplicate packet from client 2.3.9.236 port 44942 - ID: 179 due to unfinished request in component <core> module <queue> Sun Jul 7 12:52:30 2019 : Error: (18606053) Ignoring duplicate packet from client 2.3.9.236 port 42423 - ID: 180 due to unfinished request in component <core> module <queue> Sun Jul 7 12:52:31 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:32 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:33 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:34 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:35 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:36 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request. Sun Jul 7 12:52:37 2019 : Error: Something is blocking the server. There are 65536 packets in the queue, waiting to be processed. Ignoring the new request.
Then nothing but this until I had to kill -9 the process.
The underlying stack is an ldap and sql lookup. Both of those systems are well indexed with care taken to make sure they return quickly. In fact, once I restarted the radiusd daemon, I was able to immediately authenticate very quickly:
$ time radtest user password localhost:1645 1 naspassword Sent Access-Request Id 187 from 0.0.0.0:47859 to 127.0.0.1:1645 length 76 User-Name = "user" User-Password = "password" NAS-IP-Address = 192.168.103.7 NAS-Port = 1 Message-Authenticator = 0x00 Cleartext-Password = "password" Received Access-Accept Id 187 from 127.0.0.1:1645 to 127.0.0.1:47859 length 57 Service-Type = Framed-User Framed-Protocol = PPP Framed-MTU = 1492
real 0m0.035s user 0m0.017s sys 0m0.009s
Seems that starting up radtest, making a connection, asking, authenticating, and closing out in 35ms is fast enough.
I'm about to upgrade to 3.0.19, but generally don't like the guess and check method. Any reason to believe that this is a bug and if it's been fixed?
schu - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html