Freeradius 3.0.17 seems to have deadlocked on me.
Matthew Schumacher
matt.s at aptalaska.net
Fri Jul 19 20:40:44 CEST 2019
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 at 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
More information about the Freeradius-Users
mailing list