Okay, I upgraded to 3.0.19 and just had the same issue again: Wed Jul 17 00:35:29 2019 : Auth: (685401) Login incorrect (No Auth-Type found: rejecting the user via Post-Auth-Type = Reject): [user] (from client 64.186.96.236 port 16166644 cli 00:24:17:07:3F:A3) Wed Jul 17 00:35:29 2019 : Auth: (685402) Login incorrect (No Auth-Type found: rejecting the user via Post-Auth-Type = Reject): [user] (from client 64.186.96.236 port 16166645 cli 3C:90:66:DA:DB:12) Wed Jul 17 00:35:30 2019 : Auth: (685405) Login incorrect (No Auth-Type found: rejecting the user via Post-Auth-Type = Reject): [user] (from client 64.186.96.223 port 15993788 cli 3C:90:66:2D:57:1F) Wed Jul 17 00:35:30 2019 : Error: Received conflicting packet from client 64.186.123.90 port 46124 - ID: 37 due to unfinished request in module sql_wifi. Giving up on old request. Wed Jul 17 00:35:30 2019 : Auth: (685409) Login incorrect (No Auth-Type found: rejecting the user via Post-Auth-Type = Reject): [user] (from client 64.186.96.223 port 15993786 cli 08:76:FF:55:3D:6C) Wed Jul 17 00:35:30 2019 : Auth: (685413) Login incorrect (No Auth-Type found: rejecting the user via Post-Auth-Type = Reject): [user] (from client 64.186.96.237 port 15932453 cli 3C:90:66:DA:DB:A1) Wed Jul 17 00:35:31 2019 : Auth: (685416) Login incorrect (No Auth-Type found: rejecting the user via Post-Auth-Type = Reject): [user] (from client 64.186.96.236 port 16166646 cli 3C:90:66:4E:84:77) Wed Jul 17 00:35:31 2019 : Auth: (685419) Login incorrect (No Auth-Type found: rejecting the user via Post-Auth-Type = Reject): [user] (from client 64.186.96.250 port 16111177 cli 3C:90:66:F9:34:46) Wed Jul 17 00:35:32 2019 : Auth: (685422) Login incorrect (No Auth-Type found: rejecting the user via Post-Auth-Type = Reject): [user] (from client 64.186.96.236 port 16166647 cli 3C:90:66:BD:33:DB) Wed Jul 17 00:35:33 2019 : Error: Received conflicting packet from client 64.186.123.90 port 46124 - ID: 37 due to unfinished request in module sql_wifi. Giving up on old request. Wed Jul 17 00:35:38 2019 : Error: Received conflicting packet from client 64.186.123.40 port 42193 - ID: 184 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:39 2019 : Error: Received conflicting packet from client 64.186.122.9 port 39175 - ID: 127 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:39 2019 : Error: Received conflicting packet from client 64.186.122.25 port 45721 - ID: 183 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:40 2019 : Error: Received conflicting packet from client 64.186.122.14 port 37015 - ID: 95 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:41 2019 : Error: Received conflicting packet from client 64.186.123.62 port 56187 - ID: 202 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:41 2019 : Error: Received conflicting packet from client 64.186.123.40 port 42193 - ID: 184 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:42 2019 : Error: Received conflicting packet from client 64.186.122.9 port 39175 - ID: 127 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:42 2019 : Error: Received conflicting packet from client 64.186.123.57 port 59432 - ID: 59 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:42 2019 : Error: Received conflicting packet from client 64.186.122.25 port 45721 - ID: 183 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:43 2019 : Error: Received conflicting packet from client 64.186.122.14 port 37015 - ID: 95 due to unfinished request in module <queue>. Giving up on old request. Wed Jul 17 00:35:43 2019 : Error: (685424) Ignoring duplicate packet from client 64.186.96.236 port 44092 - ID: 208 due to unfinished request in component <core> module <queue> Wed Jul 17 00:35:44 2019 : Error: Received conflicting packet from client 64.186.123.62 port 56187 - ID: 202 due to unfinished request in module <queue>. Giving up on old request. It looks like my sql_wifi module is too slow and needs to be better, but it shouldn't deadlock the entire server unto the point of needing to be killed -9. Anything I can provide the devs that would help identify where the server is locking up? Backtraces? schu On 7/8/19 2:38 PM, Jorge Pereira wrote:
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
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html