Freeradius 3.0.17 seems to have deadlocked on me.

[Jorge Pereira]

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