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 bob@realm.com 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 bob@domain.com 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 bob@domain.com. But if I take bob out of the local passwd file, bob@domain.com 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 bob@domain.com 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
"Chris A. Kalin" <cak@netwurx.net> wrote:
We have bob@realm.com 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 bob@domain.com tries to log in, the proxy request goes to the remote server and it'll work.
OK...
But on 1.1.3 I get weird results. Bob (local) gets the same "disabled" message, but so does bob@domain.com. But if I take bob out of the local passwd file, bob@domain.com 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 bob@domain.com failing auth - I have to hear about it from the customer himself.
In 1.1.3, the account lockouts in /etc/passwd are handled by the unix module, unless you've got something else set up. And the unix module only has an "authenticate" handler. That means it's run only if "Auth-Type = System", and never for proxying. Please post a config & debug logs from 1.1.3. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
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 = "bob@domain.com" User-Password = "XXXX" 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 = "bob@domain.com" 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_server = no } proxy_requests = yes $INCLUDE ${confdir}/proxy.conf $INCLUDE ${confdir}/clients.conf snmp = yes $INCLUDE ${confdir}/snmp.conf thread pool { start_servers = 20 max_servers = 128 min_spare_servers = 10 max_spare_servers = 30 max_requests_per_server = 300 } modules { pap { encryption_scheme = crypt } chap { authtype = CHAP } pam { pam_auth = radiusd } unix { cache = no cache_reload = 600 radwtmp = ${logdir}/radwtmp } $INCLUDE ${confdir}/eap.conf mschap { } ldap { server = "ldap.your.domain" basedn = "o=My Org,c=UA" filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" start_tls = no access_attr = "dialupAccess" dictionary_mapping = ${raddbdir}/ldap.attrmap ldap_connections_number = 5 timeout = 4 timelimit = 3 net_timeout = 1 } realm IPASS { format = prefix delimiter = "/" ignore_default = no ignore_null = no } realm realmsuffix { format = suffix delimiter = "@" ignore_default = no ignore_null = no } realm realmpercent { format = suffix delimiter = "%" ignore_default = no ignore_null = no } realm ntdomain { format = prefix delimiter = "\\" ignore_default = no ignore_null = no } checkval { item-name = Calling-Station-Id check-name = Calling-Station-Id data-type = string } preprocess { huntgroups = ${confdir}/huntgroups hints = ${confdir}/hints with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no } files { usersfile = ${confdir}/users acctusersfile = ${confdir}/acct_users preproxy_usersfile = ${confdir}/preproxy_users compat = no } detail { detailfile = ${radacctdir}/%{Client-IP-Address}/detail detailperm = 0660 } acct_unique { key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" } $INCLUDE ${confdir}/sql.conf radutmp { filename = ${logdir}/radutmp username = %{Stripped-User-Name:-%{User-Name}} case_sensitive = no check_with_nas = yes perm = 0600 callerid = "yes" } radutmp sradutmp { filename = ${logdir}/sradutmp perm = 0644 callerid = "no" } attr_filter { attrsfile = ${confdir}/attrs } counter daily { filename = ${raddbdir}/db.daily key = User-Name count-attribute = Acct-Session-Time reset = daily counter-name = Daily-Session-Time check-name = Max-Daily-Session allowed-servicetype = Framed-User cache-size = 5000 } sqlcounter dailycounter { counter-name = Daily-Session-Time check-name = Max-Daily-Session sqlmod-inst = sql key = User-Name reset = daily query = "SELECT SUM(AcctSessionTime - \ GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) \ FROM radacct WHERE UserName='%{%k}' AND \ UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'" } sqlcounter monthlycounter { counter-name = Monthly-Session-Time check-name = Max-Monthly-Session sqlmod-inst = sql key = User-Name reset = monthly query = "SELECT SUM(AcctSessionTime - \ GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) \ FROM radacct WHERE UserName='%{%k}' AND \ UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'" } always fail { rcode = fail } always reject { rcode = reject } always ok { rcode = ok simulcount = 0 mpp = no } expr { } digest { } exec { wait = yes input_pairs = request } exec echo { wait = yes program = "/bin/echo %{User-Name}" input_pairs = request output_pairs = reply } ippool main_pool { range-start = 192.168.1.1 range-stop = 192.168.3.254 netmask = 255.255.255.0 cache-size = 800 session-db = ${raddbdir}/db.ippool ip-index = ${raddbdir}/db.ipindex override = no maximum-timeout = 0 } } instantiate { monthlycounter } authorize { preprocess chap realmsuffix files monthlycounter } authenticate { unix } preacct { preprocess acct_unique realmsuffix files } accounting { detail sql } session { sql } post-auth { } pre-proxy { } post-proxy { } -------------------- proxy.conf -------------------- proxy server { synchronous = no retry_delay = 5 retry_count = 3 dead_time = 120 default_fallback = no post_proxy_authorize = no } realm LOCAL { type = radius authhost = LOCAL accthost = LOCAL } realm domain.com { type = radius authhost = xx.xx.xx.xx:1645 accthost = xx.xx.xx.xx:1646 secret = KeyKeyKey strip } realm NULL { type = radius authhost = LOCAL accthost = LOCAL }
"Chris A. Kalin" <cak@netwurx.net> 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.
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. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Alan DeKok wrote:
"Chris A. Kalin" <cak@netwurx.net> 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!
"Chris A. Kalin" <cak@netwurx.net> 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. 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. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Alan DeKok wrote:
"Chris A. Kalin" <cak@netwurx.net> 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
"Chris A. Kalin" <cak@netwurx.net> 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.
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?
No. The behavior did not change. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Alan DeKok wrote:
"Chris A. Kalin" <cak@netwurx.net> 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 = "bob@domain.com" User-Password = "XXXX" modcall: entering group authorize modcall[authorize]: module "preprocess" returns ok rlm_realm: Looking up realm domain.com for User-Name = "bob@domain.com" 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: [bob@domain.com/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!
"Chris A. Kalin" <cak@netwurx.net> wrote:
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,
The debug log you posted for 1.1.3 doesn't show that. And again, the server behavior hasn't changed. If you think the configurations you have are the same, they're not.
Here's an output of the 0.8 server's debug log handling the exact same request:
users: Matched DEFAULT at 54 modcall[authorize]: module "files" returns ok
The 1.1.3 configuration you posted shows it matching TWO entries in the users file. This debug log shows ONE. Please believe me when I say that the behavior HAS NOT changed, and that the problem IS in your local config. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Hello All I already posted on this list about my probs with ippool. now with the help of some members on this list i got it running on a 32-Bit solaris system. now doing the same on a 64 Bit solaris system (intel 64 by dell) i only get the message ippool: Attribute Pool-Name not found there seams to be no difference in setup of the two systems. i even completelt removed the /usr/local folder on the 64-bit machine and re-installed freeradius, after that i copied the etc/raddb from the 32 system to the 64 system. i cleaned out the mysql db and dumped the contents of the db in the 32 system into it. still no change. can anyone suggest a course of action? thx in advance
"Sascha Djuric" <Sascha_Djuric@gmx.de> wrote:
I already posted on this list about my probs with ippool. now with the help of some members on this list i got it running on a 32-Bit solaris system. now doing the same on a 64 Bit solaris system (intel 64 by dell) i only get the message
ippool: Attribute Pool-Name not found
Is this 1.1.2 or 1.1.3? Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Sorry for being so sloppy, this is 1.1.3 -------- Original-Nachricht -------- Datum: Fri, 08 Sep 2006 14:07:58 -0400 Von: "Alan DeKok" <aland@deployingradius.com> An: FreeRadius users mailing list <freeradius-users@lists.freeradius.org> Betreff: Re: ippool on solatis10 32/64 bit difference
"Sascha Djuric" <Sascha_Djuric@gmx.de> wrote:
I already posted on this list about my probs with ippool. now with the help of some members on this list i got it running on a 32-Bit solaris system. now doing the same on a 64 Bit solaris system (intel 64 by dell) i only get the message
ippool: Attribute Pool-Name not found
Is this 1.1.2 or 1.1.3?
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (3)
-
Alan DeKok -
Chris A. Kalin -
Sascha Djuric