Requests being rejected with "Invalid user"

[Dan M]

> Date: Wed, 2 Dec 2020 18:01:15 -0500
> From: Alan DeKok <aland at deployingradius.com>
> 
> On Dec 2, 2020, at 5:33 PM, Dan M <dan.red.beard at gmail.com> wrote:
> >
> > We have been running FreeRadius for about 18 months with very light
> > traffic and no issues.
> > Recently, within the last month, some requests are rejected and a
> > message appears in the log Invalid user: [the actual user id] (from
> > client <the actual client id> port
> > 0)
> 
>   That message comes out when the user is rejected.
> 
> > It seems completely random.
> > The end user just hits enter again which runs thru the client system
> > and generates a new request that succeeds.
> > (Well it seems that none of the second requests have failed.  I have
> > no reports otherwise) The user id seems to me to be identical (at
> > least in the log) for both the failure and the success.
> 
>   Sure.  Sounds like a DB connection issue, TBH.

Not using a DB. 

> 
>   i.e. if FreeRADIUS can't talk to the database, it can't get the user credentials.
> So to be safe, it has to reject the user.
> 
>   Are there *other* error messages in the logs, around the same time that
> user is rejected?

Well, that's the thing.  There is NOTHING else.
I'd have expected something that might identify the reason for the rejection

> 
> > This happened on multiple instances in multiple locations.
> > Restarting the instances seemed to clear the issue for a while, but
> > it's resurfaced (after about 12 days).
> >
> > I do not think that the request is getting to the "authorize" phase
> > because there is no message from the python plug-in indicating that it
> started.
> 
>   What "python plugin?"

We are using python to make a web service call as part of authorize.
Python log has nothing for these requests.
So I'm five nines confident it isn't getting that far.
Python makes the webservice call which actually does the authentication,
and if it succeeds, sets the cleartext password to the password in the request and lets pap (the only thing in authentication section, handle the reply)
If it fails, it returns configTuple = (('Auth-Type', "Reject"),)> 

>   i.e. we don't have access to your system.  So you shouldn't assume that we
> know what you're talking about, when you refer to custom changes you
> made.

The point was it's getting rejected by something I didn't write and isn't reaching the thing I did.
I left all of these in place and haven't changed any of the files.
Authorize {
filter_username
preprocess
auth_log
suffix
expiration
logintime
python
pap
}

> 
> > So maybe this comes from some pre-authorize step?
> 
>   Maybe.  It depends on how you configured it.  If the configuration says to
> reject the user in the "authorize" stage, then it rejects the user.
> 
> > I scanned all the configuration and don't find that string "Invalid user"
> > anywhere,
> > so I'm thinking it's generated internally when something else fails.
> 
>   It's in the source.
> 
> > Unfortunately, this is in a locked-down, production environment and I
> > can't just "start it up in debug mode"
> > Is this something you have seen before?
> > Is there something I might do to increase the log level?  Where, how,
> > and of what?
> 
>   see raddb/sites-enabled/control-socket, and "radmin".

I looked at this and started a different thread about this specifically.

> 
> > We are running version 3.0.17.
> 
>   Probably upgrade to 3.0.21.  It might not help this issue, but it's not a bad
> idea.

It's on the long list of maintenance tasks for 2021

> 
>   Alan DeKok.
> 

Lastly, while most requests are generating detail request/reply entries, there are no failures in the detail-reply log.
Odd.

Dan M



Scanned by McAfee and confirmed virus-free.	
Find out more here: https://bit.ly/2zCJMrO