Re: Proxy problem in FreeRADIUS 1.1.3
Alan DeKok wrote: "Chris A. Kalin" <[EMAIL PROTECTED]> wrote: Right, the users file has a default Auth-Type := System Yes, which doesn't affect anything, because the unix module is only used during authentication, and it's proxying, so it's not hitting the unix module. This makes sense. What I don't get is why the request is sailing through the proxy module (where it apparently receives an "Access-Accept") and then continues INTO the files/unix part of the config, which is where the failure occurs - with no log of the failure to radius.log. Here's an output of the 0.8 server's debug log handling the exact same request: rad_recv: Access-Request packet from host yy.yy.yy.31:1354, id=2, length=60 User-Name = "[EMAIL PROTECTED]" User-Password = "" modcall: entering group authorize modcall[authorize]: module "preprocess" returns ok rlm_realm: Looking up realm domain.com for User-Name = "[EMAIL PROTECTED]" rlm_realm: Found realm domain.com rlm_realm: Adding Stripped-User-Name = "bob" rlm_realm: Proxying request from user bob to realm domain.com rlm_realm: Adding Realm = "domain.com" rlm_realm: Preparing to proxy authentication request to realm domain.com modcall[authorize]: module "realmat" returns updated rlm_sqlcounter: Entering module authorize code rlm_sqlcounter: Could not find Check item value pair modcall[authorize]: module "monthlycounter" returns noop users: Matched DEFAULT at 54 modcall[authorize]: module "files" returns ok rlm_sqlcounter: Entering module authorize code rlm_sqlcounter: Could not find Check item value pair modcall[authorize]: module "monthlycounter" returns noop modcall: group authorize returns updated Sending Access-Request of id 1 to xx.xx.xx.xx:1645 User-Name = "bob" User-Password = "\004\315\007\274\t\214\006\315\315JO\344\330\337\275I" NAS-IP-Address = yy.yy.yy.31 Proxy-State = "2" --- Walking the entire request list --- Waking up in 6 seconds... rad_recv: Access-Accept packet from host xx.xx.xx.xx:1645, id=1, length=47 Service-Type = Framed-User Framed-Protocol = PPP Session-Timeout = 57600 Idle-Timeout = 900 Proxy-State = 0x32 modcall: entering group authorize modcall[authorize]: module "preprocess" returns ok rlm_realm: Proxy reply, or no user name. Ignoring. modcall[authorize]: module "realmat" returns noop rlm_sqlcounter: Entering module authorize code rlm_sqlcounter: Could not find Check item value pair modcall[authorize]: module "monthlycounter" returns noop users: Matched DEFAULT at 54 modcall[authorize]: module "files" returns ok rlm_sqlcounter: Entering module authorize code rlm_sqlcounter: Could not find Check item value pair modcall[authorize]: module "monthlycounter" returns noop modcall: group authorize returns ok rad_check_password: Found Auth-Type System rad_check_password: Auth-Type = Accept, accepting the user Login OK: [EMAIL PROTECTED]/Password] (from client yy.yy.yy.31 port 0) Sending Access-Accept of id 2 to yy.yy.yy.31:1354 Service-Type = Framed-User Framed-Protocol = PPP Session-Timeout = 57600 Idle-Timeout = 900 Finished request 0 Going to the next request rl_next: returning NULL Waking up in 6 seconds... --- Walking the entire request list --- Cleaning up request 0 ID 2 with timestamp 4501e9a6 Nothing to do. Sleeping until we see a request. I'll admit there are some steps in there that don't make sense to me either, which suggests that maybe I was relying on a bug or bad behavior before. But even so, if nothing changed, then I should be getting the same bug or bad behavior now, right? If I'm doing this completely wrong in the first place and was simply lucking out before, tell me that and I'll try to learn the correct way. The users file is identical in the 0.8 and 1.1.3 servers, and the radiusd.conf file had minimal changes - I can upload the 0.8 radiusd.conf if you think it'll help. Thanks! - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Re: Proxy problem in FreeRADIUS 1.1.3
Alan DeKok wrote: "Chris A. Kalin" <[EMAIL PROTECTED]> wrote: That's exactly riight, but why is it even getting to my users file? Because you configured it that way? It's supposed to be proxying the auth request to another box, and apparently does, but then it charges ahead and checks the username against the local password database anyway What local password database? It's looking at the "users" file. Right, the users file has a default Auth-Type := System, so when I was talking about the "users" file, I was talking about "the users file where either passwords are specifically stored or it tells RADIUS to use /etc/passwd authentication." Sorry for not being specific enough. My bad. If you don't want it to look at the "users" file, update the configuration so that the "users" file is run ONLY when the realm module doesn't find a realm. See the debug output for what the realm module returns when it does/doesn't find a realm, and see doc/configurable_failover for how to configure the "authorize" section to run "files" only if a realm isn't found. An identical users file with the same proxy.conf and (as similiar as it can be) radiusd.conf under an older FreeRADIUS doesn't do this. You're saying it used to stop processing "authorize" after the "realms" module was run, simply because the module added Proxy-To-Realm. The server NEVER did that. Ever. So just so I completely understand, _did_ the server's (or one or more modules') behavior related to all this change between 0.8 and 1.1.3? If not, why did this work in an older version and not now? Thanks for all your help! Chris - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Re: Proxy problem in FreeRADIUS 1.1.3
Alan DeKok wrote: "Chris A. Kalin" <[EMAIL PROTECTED]> wrote: Sending Access-Reject of id 3 to xx.xx.xx.xx port 4587 Reply-Message = "Your account has been disabled." That message does not appear in the server source. It's added somewhere by your local config. Right, in the users file. I knew that one already, sorry I didn't post the users files. Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: calling files (rlm_files) for request 2 Fri Sep 8 12:37:40 2006 : Debug: users: Matched entry DEFAULT at line 54 Fri Sep 8 12:37:40 2006 : Debug: users: Matched entry DEFAULT at line 72 Check those two lines. Find the entry in your configuration files that adds that Reply-Message, it's setting Auth-Type := Reject, too. That's exactly riight, but why is it even getting to my users file? It's supposed to be proxying the auth request to another box, and apparently does, but then it charges ahead and checks the username against the local password database anyway, and finds a local user with a GID that generates the "Your account has been disabled" message. It's like it's proxying the request but doesn't stop once it gets a hit. An identical users file with the same proxy.conf and (as similiar as it can be) radiusd.conf under an older FreeRADIUS doesn't do this. And more importantly, it's not logging _anything_ to my radius.log (in the event of this particular failure I mean, other logs work fine), which is the first time I've ever seen that happen in FreeRADIUS. If the remote end rejects the user I get a "remote host says so" or similar error. Right now I'm not getting anything. Thanks! - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Re: Proxy problem in FreeRADIUS 1.1.3
Please post a config & debug logs from 1.1.3.
OK, I took out blank lines, commented lines, and obfuscated IPs and
passwords. Let me know if there's anything else I can provide, and
thanks in advance for all your help!
-- radiusd -X -x debug output
rad_recv: Access-Request packet from host xx.xx.xx.xx:4587, id=3, length=60
User-Name = "[EMAIL PROTECTED]"
User-Password = ""
Fri Sep 8 12:37:40 2006 : Debug: Processing the authorize section of
radiusd.conf
Fri Sep 8 12:37:40 2006 : Debug: modcall: entering group authorize for
request 2
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 2
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 2
Fri Sep 8 12:37:40 2006 : Debug: modcall[authorize]: module
"preprocess" returns ok for request 2
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: calling chap
(rlm_chap) for request 2
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: returned from
chap (rlm_chap) for request 2
Fri Sep 8 12:37:40 2006 : Debug: modcall[authorize]: module "chap"
returns noop for request 2
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: calling
realmsuffix (rlm_realm) for request 2
Fri Sep 8 12:37:40 2006 : Debug: rlm_realm: Looking up realm
"domain.com" for User-Name = "[EMAIL PROTECTED]"
Fri Sep 8 12:37:40 2006 : Debug: rlm_realm: Found realm "domain.com"
Fri Sep 8 12:37:40 2006 : Debug: rlm_realm: Adding
Stripped-User-Name = "bob"
Fri Sep 8 12:37:40 2006 : Debug: rlm_realm: Proxying request from
user bob to realm domain.com
Fri Sep 8 12:37:40 2006 : Debug: rlm_realm: Adding Realm = "domain.com"
Fri Sep 8 12:37:40 2006 : Debug: rlm_realm: Preparing to proxy
authentication request to realm "domain.com"
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: returned from
realmsuffix (rlm_realm) for request 2
Fri Sep 8 12:37:40 2006 : Debug: modcall[authorize]: module
"realmsuffix" returns updated for request 2
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: calling files
(rlm_files) for request 2
Fri Sep 8 12:37:40 2006 : Debug: users: Matched entry DEFAULT at
line 54
Fri Sep 8 12:37:40 2006 : Debug: users: Matched entry DEFAULT at
line 72
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: returned from
files (rlm_files) for request 2
Fri Sep 8 12:37:40 2006 : Debug: modcall[authorize]: module "files"
returns ok for request 2
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: calling
monthlycounter (rlm_sqlcounter) for request 2
Fri Sep 8 12:37:40 2006 : Debug: rlm_sqlcounter: Entering module
authorize code
Fri Sep 8 12:37:40 2006 : Debug: rlm_sqlcounter: Could not find Check
item value pair
Fri Sep 8 12:37:40 2006 : Debug: modsingle[authorize]: returned from
monthlycounter (rlm_sqlcounter) for request 2
Fri Sep 8 12:37:40 2006 : Debug: modcall[authorize]: module
"monthlycounter" returns noop for request 2
Fri Sep 8 12:37:40 2006 : Debug: modcall: leaving group authorize
(returns updated) for request 2
Fri Sep 8 12:37:40 2006 : Debug: Cancelling proxy as request was
already rejected
Fri Sep 8 12:37:40 2006 : Debug: Request 2 rejected in proxy_send.
Fri Sep 8 12:37:40 2006 : Debug: Server rejecting request 2.
Sending Access-Reject of id 3 to xx.xx.xx.xx port 4587
Reply-Message = "Your account has been disabled."
Fri Sep 8 12:37:40 2006 : Debug: Finished request 2
Fri Sep 8 12:37:40 2006 : Debug: Going to the next request
Fri Sep 8 12:37:40 2006 : Debug: --- Walking the entire request list ---
Fri Sep 8 12:37:40 2006 : Debug: Waking up in 6 seconds...
Fri Sep 8 12:37:46 2006 : Debug: --- Walking the entire request list ---
Fri Sep 8 12:37:46 2006 : Debug: Cleaning up request 2 ID 3 with
timestamp 4501aa64
Fri Sep 8 12:37:46 2006 : Debug: Nothing to do. Sleeping until we see
a request.
-- radiusd.conf -
prefix = /usr/local
exec_prefix = ${prefix}
sysconfdir = ${prefix}/etc
localstatedir = ${prefix}/var
sbindir = ${exec_prefix}/sbin
logdir = ${localstatedir}/log/radius
raddbdir = ${sysconfdir}/raddb
radacctdir = ${logdir}/radacct
confdir = ${raddbdir}
run_dir = ${localstatedir}/run/radiusd
log_file = ${logdir}/radius.log
libdir = ${exec_prefix}/lib
pidfile = ${run_dir}/radiusd.pid
user = root
group = radius
max_request_time = 30
delete_blocked_requests = no
cleanup_delay = 5
max_requests = 8000
bind_address = xx.xx.xx.xx
port = 0
hostname_lookups = no
allow_core_dumps = no
regular_expressions = yes
extended_expressions= yes
log_stripped_names = no
log_auth = yes
log_auth_badpass = yes
log_auth_goodpass = yes
usercollide = no
lower_user = no
lower_pass = no
nospace_user = no
nospace_pass = no
checkrad = ${sbindir}/checkrad
security {
max_attributes = 200
reject_delay = 0
status_ser
Proxy problem in FreeRADIUS 1.1.3
OK, I've got a bit of a weird issue here. I've beat my head against it and I'm turning to the list for help. I have local UNIX authentication, and I also proxy a few realms. The problem seems to arise when I have the same username both locally and going to a particular realm. We have [EMAIL PROTECTED] and bob. Bob (the local user) is disabled, he's in a certain group on my server that locks him out completely. On my backup RADIUS server, which is version 0.8-pre, I get the expected behavior - if bob tries to log in, he gets a "Your account has been disabled" message, but if [EMAIL PROTECTED] tries to log in, the proxy request goes to the remote server and it'll work. But on 1.1.3 I get weird results. Bob (local) gets the same "disabled" message, but so does [EMAIL PROTECTED] But if I take bob out of the local passwd file, [EMAIL PROTECTED] proxies to where it's supposed to go and works fine. What's even weirder is in the above failure, I don't even get anything in radius.log about [EMAIL PROTECTED] failing auth - I have to hear about it from the customer himself. I'm assuming something major changed in the proxy code in the past, what, four years? But this is kind of a show stopper for me, so any help would be appreciated. I can post whatever config files anyone needs, but maybe I'm just missing something stupid here. Thanks in advance! Chris Kalin - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
