Last call for 2.1.10

[John Horne]

On Wed, 2010-09-22 at 15:15 +0200, Alan DeKok wrote:
> I've put some preliminary tar files on:
> 
> http://git.freeradius.org/pre/
> 
>   If there are any issues, let me know now.
>
We have an issue but I am a little lost as to where things are going
wrong.

If I set the uid/gid and 'mode=rw' in control-socket, and then restart
the radiusd process, all is okay. However, if I then run 'radmin -e
hup', the radius log file shows the re-reading of the config file and
modules being reloaded, but *some* of our users cannot then
authenticate.

The server provides authentication for both wireless users and VPN
users. For wireless users the wireless lan controller talks to the
radius server, and the server proxies the request on to a backed IAS
server. This works fine in all instances. The VPN users take a slightly
different route in that they use a PPTP connection, which calls a PPP
radius.so object. This in turn accesses the radius server (which is
running on the same host), and that proxies the request off as with
wireless users.

The problem seems to be that although the proxy server returns a 'Yes'
reply (meaning the user is authenticated) for the VPN users, the pppd
process does not seem to recognise it and treats it as a failed CHAP
authentication. As such what we see is the radius log saying the user
has authenticated okay, but the user receives a 691 (I think) code
indicating that there is a problem with their userid/password.

Why this only occurs when we use 'radmin -e hup' I don't know. I can
only guess that maybe something isn't being reloaded. If we do not use
the control-socket then it all works fine for all our users.

I have - finally - got this working (or rather failing) on a test
server. So I can try to tackle the problem without affecting our live
servers.

A small log file snippet from the server:

The radius log shows (having just issued 'radmin -e hup'):

============================================================
Wed Sep 22 16:41:57 2010 : Info: Received HUP signal.
Wed Sep 22 16:41:57 2010 : Info: HUP - Re-reading configuration files
Wed Sep 22 16:41:57 2010 : Info: HUP - loading modules
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module "suffix"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module "acct_log"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module
"attr_filter.post-proxy"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module "radutmp"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module "suffix"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module
"attr_filter.post-proxy"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module
"attr_filter.access_reject"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module
"attr_filter.accounting_response"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module "radutmp"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module "pap"
Wed Sep 22 16:41:57 2010 : Info:  Module: Reloaded module "files"
Wed Sep 22 16:41:57 2010 : Info: Loaded virtual server inner-tunnel
Wed Sep 22 16:41:57 2010 : Info: Loaded virtual server <default>
Wed Sep 22 16:41:57 2010 : Info:  ... closing socket command
file /var/run/radiusd/radiusd.sock
Wed Sep 22 16:42:38 2010 : Auth: Login OK: [jhorne] (from client
localhost port 0 cli 141.163.60.7)
============================================================


However, our daemon log file shows:

============================================================
Sep 22 16:42:37 jhvm1 pppd[27048]: rcvd [CHAP Response id=0xd3
<4a95b44a8179d661b7dc7036d88274d00000000000000000b309bacedf503df09b5c81ed196320a2c3a6accc68c1f70600>, name = "jhorne"]
Sep 22 16:42:38 jhvm1 pppd[27048]: Yes
Sep 22 16:42:38 jhvm1 pppd[27048]: Peer jhorne failed CHAP
authentication
Sep 22 16:42:38 jhvm1 pppd[27048]: sent [CHAP Failure id=0xd3 "Yes\n"]
Sep 22 16:42:38 jhvm1 pppd[27048]: sent [LCP TermReq id=0x2
"Authentication failed"]
============================================================


The 'Yes' is returned by the proxy server. For some reason pppd is
logging this and treating it as a chap failure. Normally it does not log
the reply as text, but instead sends a chap response:

============================================================
Sep 22 16:45:00 jhvm1 pppd[27176]: rcvd [CHAP Response id=0xc8
<ff1620e9777e6dcb8e906e0fa61ce86d00000000000000004fcd1bb474b5278994d471503893a392f3a596b66fb4532000>, name = "jhorne"]
Sep 22 16:45:00 jhvm1 pppd[27176]: sent [CHAP Success id=0xc8
"S=B18D5D0EC139ECCB0D17EBADF2DE818BCD7DF55B"]
============================================================


Although this looks like a pppd problem, it only occurs after we have
issued 'radmin -e hup'. If we don't use the control-socket, or just use
it without issuing a 'hup', then pppd works fine.




John.

-- 
John Horne                   Tel: +44 (0)1752 587287
University of Plymouth, UK   Fax: +44 (0)1752 587001