Alan DeKok schrieb:
Please check current CVS. In cases where it doesn't work, it should now print an error. This means that configurations you *think* work, but which don't really work, will now print an error.
Ok, I've tried it, but there is no change. I include my sample config that you can try it yourself. I'm quite sure that I've included the patch from CVS to modcall.c and actually have re-compiled the server:
# strings /usr/sbin/freeradius | grep modcall.c $Id: modcall.c,v 1.86 2007/07/05 15:01:21 aland Exp $
But maybe I've made a mistake, so please verify my results. Debuglog with cumbersome workaround enabled:
Thu Jul 5 20:51:34 2007 : Info: Starting - reading configuration files ... Thu Jul 5 20:51:34 2007 : Debug: read_config_files: reading dictionary Thu Jul 5 20:51:34 2007 : Debug: main { Thu Jul 5 20:51:34 2007 : Debug: prefix = "/usr" Thu Jul 5 20:51:34 2007 : Debug: localstatedir = "/var" Thu Jul 5 20:51:34 2007 : Debug: logdir = "/var/log/freeradius" Thu Jul 5 20:51:34 2007 : Debug: libdir = "/usr/lib/freeradius" Thu Jul 5 20:51:34 2007 : Debug: radacctdir = "/var/log/freeradius/radacct" Thu Jul 5 20:51:34 2007 : Debug: hostname_lookups = no Thu Jul 5 20:51:34 2007 : Debug: snmp = no Thu Jul 5 20:51:34 2007 : Debug: max_request_time = 30 Thu Jul 5 20:51:34 2007 : Debug: cleanup_delay = 5 Thu Jul 5 20:51:34 2007 : Debug: max_requests = 1024 Thu Jul 5 20:51:34 2007 : Debug: allow_core_dumps = no Thu Jul 5 20:51:34 2007 : Debug: log_stripped_names = no Thu Jul 5 20:51:34 2007 : Debug: log_file = "/var/log/freeradius/radius.log" Thu Jul 5 20:51:34 2007 : Debug: log_auth = yes Thu Jul 5 20:51:34 2007 : Debug: log_auth_badpass = yes Thu Jul 5 20:51:34 2007 : Debug: log_auth_goodpass = yes Thu Jul 5 20:51:34 2007 : Debug: pidfile = "/var/run/freeradius/freeradius.pid" Thu Jul 5 20:51:34 2007 : Debug: user = "freerad" Thu Jul 5 20:51:34 2007 : Debug: group = "freerad" Thu Jul 5 20:51:34 2007 : Debug: checkrad = "/usr/sbin/checkrad" Thu Jul 5 20:51:34 2007 : Debug: debug_level = 0 Thu Jul 5 20:51:34 2007 : Debug: proxy_requests = no Thu Jul 5 20:51:34 2007 : Debug: security { Thu Jul 5 20:51:34 2007 : Debug: max_attributes = 200 Thu Jul 5 20:51:34 2007 : Debug: reject_delay = 0 Thu Jul 5 20:51:34 2007 : Debug: status_server = yes Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: listen { Thu Jul 5 20:51:34 2007 : Debug: type = "auth" Thu Jul 5 20:51:34 2007 : Debug: ipaddr = * Thu Jul 5 20:51:34 2007 : Debug: port = 0 Thu Jul 5 20:51:34 2007 : Debug: client 172.27.128.219 { Thu Jul 5 20:51:34 2007 : Debug: secret = "testing123" Thu Jul 5 20:51:34 2007 : Debug: shortname = "localextern" Thu Jul 5 20:51:34 2007 : Debug: nastype = "other" Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: client 127.0.0.1 { Thu Jul 5 20:51:34 2007 : Debug: secret = "testing123" Thu Jul 5 20:51:34 2007 : Debug: shortname = "localhost" Thu Jul 5 20:51:34 2007 : Debug: nastype = "other" Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: radiusd: entering modules setup Thu Jul 5 20:51:34 2007 : Debug: radiusd: Library search path is /usr/lib/freeradius Thu Jul 5 20:51:34 2007 : Debug: modules: Not loading preacct{} section Thu Jul 5 20:51:34 2007 : Debug: modules: Not loading accounting{} section Thu Jul 5 20:51:34 2007 : Debug: modules: Not loading pre-proxy{} section Thu Jul 5 20:51:34 2007 : Debug: modules: Not loading post-proxy{} section Thu Jul 5 20:51:34 2007 : Debug: server { Thu Jul 5 20:51:34 2007 : Debug: modules { Thu Jul 5 20:51:34 2007 : Debug: Module: Checking authenticate {...} for more modules to load Thu Jul 5 20:51:34 2007 : Debug: (Loaded rlm_pap, checking if it's valid) Thu Jul 5 20:51:34 2007 : Debug: Module: Linked to module rlm_pap Thu Jul 5 20:51:34 2007 : Debug: Module: Instantiating pap Thu Jul 5 20:51:34 2007 : Debug: pap { Thu Jul 5 20:51:34 2007 : Debug: encryption_scheme = "auto" Thu Jul 5 20:51:34 2007 : Debug: auto_header = yes Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: >>> CALLING EVALUATE ok) Thu Jul 5 20:51:34 2007 : Debug: >>> LOOKING AT ok) Thu Jul 5 20:51:34 2007 : Debug: >>> I0 23:ok Thu Jul 5 20:51:34 2007 : Debug: >>> EVALUATE 0 ::):: Thu Jul 5 20:51:34 2007 : Debug: >>> AT EOL2a Thu Jul 5 20:51:34 2007 : Debug: >>> EVALUATE RETURNED ::):: Thu Jul 5 20:51:34 2007 : Debug: >>> AT EOL Thu Jul 5 20:51:34 2007 : Debug: >>> CALLING EVALUATE reject) Thu Jul 5 20:51:34 2007 : Debug: >>> LOOKING AT reject) Thu Jul 5 20:51:34 2007 : Debug: >>> I0 23:reject Thu Jul 5 20:51:34 2007 : Debug: >>> EVALUATE 0 ::):: Thu Jul 5 20:51:34 2007 : Debug: >>> AT EOL2a Thu Jul 5 20:51:34 2007 : Debug: >>> EVALUATE RETURNED ::):: Thu Jul 5 20:51:34 2007 : Debug: >>> AT EOL Thu Jul 5 20:51:34 2007 : Debug: Module: Checking authorize {...} for more modules to load Thu Jul 5 20:51:34 2007 : Debug: (Loaded rlm_files, checking if it's valid) Thu Jul 5 20:51:34 2007 : Debug: Module: Linked to module rlm_files Thu Jul 5 20:51:34 2007 : Debug: Module: Instantiating files Thu Jul 5 20:51:34 2007 : Debug: files { Thu Jul 5 20:51:34 2007 : Debug: usersfile = "/etc/freeradius/users" Thu Jul 5 20:51:34 2007 : Debug: acctusersfile = "/dev/null" Thu Jul 5 20:51:34 2007 : Debug: preproxy_usersfile = "/dev/null" Thu Jul 5 20:51:34 2007 : Debug: compat = "no" Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: Initializing the thread pool... Thu Jul 5 20:51:34 2007 : Debug: thread pool { Thu Jul 5 20:51:34 2007 : Debug: start_servers = 5 Thu Jul 5 20:51:34 2007 : Debug: max_servers = 32 Thu Jul 5 20:51:34 2007 : Debug: min_spare_servers = 3 Thu Jul 5 20:51:34 2007 : Debug: max_spare_servers = 10 Thu Jul 5 20:51:34 2007 : Debug: max_requests_per_server = 0 Thu Jul 5 20:51:34 2007 : Debug: cleanup_delay = 5 Thu Jul 5 20:51:34 2007 : Debug: max_queue_size = 65536 Thu Jul 5 20:51:34 2007 : Debug: } Thu Jul 5 20:51:34 2007 : Debug: Thread spawned new child 1. Total threads in pool: 1 Thu Jul 5 20:51:34 2007 : Debug: Thread 1 waiting to be assigned a request Thu Jul 5 20:51:34 2007 : Debug: Thread spawned new child 2. Total threads in pool: 2 Thu Jul 5 20:51:34 2007 : Debug: Thread 2 waiting to be assigned a request Thu Jul 5 20:51:34 2007 : Debug: Thread spawned new child 3. Total threads in pool: 3 Thu Jul 5 20:51:34 2007 : Debug: Thread 3 waiting to be assigned a request Thu Jul 5 20:51:34 2007 : Debug: Thread spawned new child 4. Total threads in pool: 4 Thu Jul 5 20:51:34 2007 : Debug: Thread 4 waiting to be assigned a request Thu Jul 5 20:51:34 2007 : Debug: Thread spawned new child 5. Total threads in pool: 5 Thu Jul 5 20:51:34 2007 : Debug: Thread 5 waiting to be assigned a request Thu Jul 5 20:51:34 2007 : Debug: Thread pool initialized Thu Jul 5 20:51:34 2007 : Debug: Listening on authentication address * port 1812 Thu Jul 5 20:51:34 2007 : Info: Ready to process requests. Thu Jul 5 20:51:34 2007 : Debug: Nothing to do. Sleeping until we see a request. rad_recv: Access-Request packet from host 127.0.0.1 port 53827, id=190, length=44 Thu Jul 5 20:42:08 2007 : Debug: Threads: total/active/spare threads = 5/0/5 Thu Jul 5 20:42:08 2007 : Debug: Thread 1 got semaphore Thu Jul 5 20:42:08 2007 : Debug: Thread 1 handling request 0, (1 handled so far) User-Name = "john" User-Password = "secret" Thu Jul 5 20:42:08 2007 : Debug: +- entering group authorize Thu Jul 5 20:42:08 2007 : Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Thu Jul 5 20:42:08 2007 : Debug: users: Matched entry john at line 1 Thu Jul 5 20:42:08 2007 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Thu Jul 5 20:42:08 2007 : Debug: ++[files] returns ok Thu Jul 5 20:42:08 2007 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Thu Jul 5 20:42:08 2007 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0 Thu Jul 5 20:42:08 2007 : Debug: ++[pap] returns updated Thu Jul 5 20:42:08 2007 : Debug: rad_check_password: Found Auth-Type Thu Jul 5 20:42:08 2007 : Debug: auth: type "PAP" Thu Jul 5 20:42:08 2007 : Debug: +- entering group PAP Thu Jul 5 20:42:08 2007 : Debug: ++- entering group pap-with-message Thu Jul 5 20:42:08 2007 : Debug: modsingle[authenticate]: calling pap (rlm_pap) for request 0 Thu Jul 5 20:42:08 2007 : Debug: rlm_pap: login attempt with password secret Thu Jul 5 20:42:08 2007 : Debug: rlm_pap: Using clear text password. Thu Jul 5 20:42:08 2007 : Debug: rlm_pap: User authenticated successfully Thu Jul 5 20:42:08 2007 : Debug: modsingle[authenticate]: returned from pap (rlm_pap) for request 0 Thu Jul 5 20:42:08 2007 : Debug: +++[pap] returns ok Thu Jul 5 20:42:08 2007 : Debug: +++? if (ok) Thu Jul 5 20:42:08 2007 : Debug: >>> CALLING EVALUATE ok) Thu Jul 5 20:42:08 2007 : Debug: >>> LOOKING AT ok) Thu Jul 5 20:42:08 2007 : Debug: ? Evaluating "ok" -> TRUE Thu Jul 5 20:42:08 2007 : Debug: >>> I0 23:ok Thu Jul 5 20:42:08 2007 : Debug: >>> EVALUATE 1 ::):: Thu Jul 5 20:42:08 2007 : Debug: >>> AT EOL2a Thu Jul 5 20:42:08 2007 : Debug: >>> EVALUATE RETURNED ::):: Thu Jul 5 20:42:08 2007 : Debug: >>> AT EOL Thu Jul 5 20:42:08 2007 : Debug: +++? if (ok) -> TRUE Thu Jul 5 20:42:08 2007 : Debug: +++- entering if (ok) Thu Jul 5 20:42:08 2007 : Debug: ::: FROM 1 TO 0 MAX 1 Thu Jul 5 20:42:08 2007 : Debug: ::: Examining Reply-Message Thu Jul 5 20:42:08 2007 : Debug: ::: APPENDING Reply-Message FROM 0 TO 0 Thu Jul 5 20:42:08 2007 : Debug: ::: TO in 0 out 1 Thu Jul 5 20:42:08 2007 : Debug: ::: to[0] = Reply-Message Thu Jul 5 20:42:08 2007 : Debug: ++++[reply] returns updated Thu Jul 5 20:42:08 2007 : Debug: +++- if (ok) returns updated Thu Jul 5 20:42:08 2007 : Debug: +++ ... skipping elsif for request 0: Preceding "if" was taken Thu Jul 5 20:42:08 2007 : Debug: ++- group pap-with-message returns ok Thu Jul 5 20:42:08 2007 : Auth: Login OK: [john/secret] (from client localhost port 0) Sending Access-Accept of id 190 to 127.0.0.1 port 53827 Reply-Message := "pap authenticate returned OK" Thu Jul 5 20:42:08 2007 : Debug: Finished request 0 state 5 Thu Jul 5 20:42:08 2007 : Debug: Going to the next request Thu Jul 5 20:42:08 2007 : Debug: Thread 1 waiting to be assigned a request Thu Jul 5 20:42:08 2007 : Debug: Waking up in 4 seconds... rad_recv: Access-Request packet from host 127.0.0.1 port 53828, id=177, length=44 Thu Jul 5 20:42:10 2007 : Debug: Thread 2 got semaphore Thu Jul 5 20:42:10 2007 : Debug: Thread 2 handling request 1, (1 handled so far) User-Name = "john" User-Password = "bad" Thu Jul 5 20:42:10 2007 : Debug: +- entering group authorize Thu Jul 5 20:42:10 2007 : Debug: modsingle[authorize]: calling files (rlm_files) for request 1 Thu Jul 5 20:42:10 2007 : Debug: users: Matched entry john at line 1 Thu Jul 5 20:42:10 2007 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 1 Thu Jul 5 20:42:10 2007 : Debug: ++[files] returns ok Thu Jul 5 20:42:10 2007 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 1 Thu Jul 5 20:42:10 2007 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 1 Thu Jul 5 20:42:10 2007 : Debug: ++[pap] returns updated Thu Jul 5 20:42:10 2007 : Debug: rad_check_password: Found Auth-Type Thu Jul 5 20:42:10 2007 : Debug: auth: type "PAP" Thu Jul 5 20:42:10 2007 : Debug: +- entering group PAP Thu Jul 5 20:42:10 2007 : Debug: ++- entering group pap-with-message Thu Jul 5 20:42:10 2007 : Debug: modsingle[authenticate]: calling pap (rlm_pap) for request 1 Thu Jul 5 20:42:10 2007 : Debug: rlm_pap: login attempt with password bad Thu Jul 5 20:42:10 2007 : Debug: rlm_pap: Using clear text password. Thu Jul 5 20:42:10 2007 : Debug: rlm_pap: Passwords don't match Thu Jul 5 20:42:10 2007 : Debug: modsingle[authenticate]: returned from pap (rlm_pap) for request 1 Thu Jul 5 20:42:10 2007 : Debug: +++[pap] returns reject Thu Jul 5 20:42:10 2007 : Debug: +++? if (ok) Thu Jul 5 20:42:10 2007 : Debug: >>> CALLING EVALUATE ok) Thu Jul 5 20:42:10 2007 : Debug: >>> LOOKING AT ok) Thu Jul 5 20:42:10 2007 : Debug: ? Evaluating "ok" -> FALSE Thu Jul 5 20:42:10 2007 : Debug: >>> I0 23:ok Thu Jul 5 20:42:10 2007 : Debug: >>> EVALUATE 1 ::):: Thu Jul 5 20:42:10 2007 : Debug: >>> AT EOL2a Thu Jul 5 20:42:10 2007 : Debug: >>> EVALUATE RETURNED ::):: Thu Jul 5 20:42:10 2007 : Debug: >>> AT EOL Thu Jul 5 20:42:10 2007 : Debug: +++? if (ok) -> FALSE Thu Jul 5 20:42:10 2007 : Debug: +++? elsif (reject) Thu Jul 5 20:42:10 2007 : Debug: >>> CALLING EVALUATE reject) Thu Jul 5 20:42:10 2007 : Debug: >>> LOOKING AT reject) Thu Jul 5 20:42:10 2007 : Debug: ? Evaluating "reject" -> TRUE Thu Jul 5 20:42:10 2007 : Debug: >>> I0 23:reject Thu Jul 5 20:42:10 2007 : Debug: >>> EVALUATE 1 ::):: Thu Jul 5 20:42:10 2007 : Debug: >>> AT EOL2a Thu Jul 5 20:42:10 2007 : Debug: >>> EVALUATE RETURNED ::):: Thu Jul 5 20:42:10 2007 : Debug: >>> AT EOL Thu Jul 5 20:42:10 2007 : Debug: +++? elsif (reject) -> TRUE Thu Jul 5 20:42:10 2007 : Debug: +++- entering elsif (reject) Thu Jul 5 20:42:10 2007 : Debug: ::: FROM 1 TO 0 MAX 1 Thu Jul 5 20:42:10 2007 : Debug: ::: Examining Reply-Message Thu Jul 5 20:42:10 2007 : Debug: ::: APPENDING Reply-Message FROM 0 TO 0 Thu Jul 5 20:42:10 2007 : Debug: ::: TO in 0 out 1 Thu Jul 5 20:42:10 2007 : Debug: ::: to[0] = Reply-Message Thu Jul 5 20:42:10 2007 : Debug: ++++[reply] returns updated Thu Jul 5 20:42:10 2007 : Debug: +++- elsif (reject) returns updated Thu Jul 5 20:42:10 2007 : Debug: ++- group pap-with-message returns reject Thu Jul 5 20:42:10 2007 : Debug: auth: Failed to validate the user. Thu Jul 5 20:42:10 2007 : Auth: Login incorrect (rlm_pap: CLEAR TEXT password check failed): [john/bad] (from client localhost port 0) Sending Access-Reject of id 177 to 127.0.0.1 port 53828 Reply-Message := "pap authenticate returned REJECT"
As you can see, the config file is still accepted. Debuglog without cumbersome workaround (elsif case only):
rad_recv: Access-Request packet from host 127.0.0.1 port 53849, id=2, length=44 Thu Jul 5 20:51:43 2007 : Debug: Thread 2 got semaphore Thu Jul 5 20:51:43 2007 : Debug: Thread 2 handling request 1, (1 handled so far) User-Name = "john" User-Password = "bad" Thu Jul 5 20:51:43 2007 : Debug: +- entering group authorize Thu Jul 5 20:51:43 2007 : Debug: modsingle[authorize]: calling files (rlm_files) for request 1 Thu Jul 5 20:51:43 2007 : Debug: users: Matched entry john at line 1 Thu Jul 5 20:51:43 2007 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 1 Thu Jul 5 20:51:43 2007 : Debug: ++[files] returns ok Thu Jul 5 20:51:43 2007 : Debug: modsingle[authorize]: calling pap (rlm_pap) for request 1 Thu Jul 5 20:51:43 2007 : Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 1 Thu Jul 5 20:51:43 2007 : Debug: ++[pap] returns updated Thu Jul 5 20:51:43 2007 : Debug: rad_check_password: Found Auth-Type Thu Jul 5 20:51:43 2007 : Debug: auth: type "PAP" Thu Jul 5 20:51:43 2007 : Debug: +- entering group PAP Thu Jul 5 20:51:43 2007 : Debug: ++- entering group pap-with-message Thu Jul 5 20:51:43 2007 : Debug: modsingle[authenticate]: calling pap (rlm_pap) for request 1 Thu Jul 5 20:51:43 2007 : Debug: rlm_pap: login attempt with password bad Thu Jul 5 20:51:43 2007 : Debug: rlm_pap: Using clear text password. Thu Jul 5 20:51:43 2007 : Debug: rlm_pap: Passwords don't match Thu Jul 5 20:51:43 2007 : Debug: modsingle[authenticate]: returned from pap (rlm_pap) for request 1 Thu Jul 5 20:51:43 2007 : Debug: +++[pap] returns reject Thu Jul 5 20:51:43 2007 : Debug: +++? if (ok) Thu Jul 5 20:51:43 2007 : Debug: >>> CALLING EVALUATE ok) Thu Jul 5 20:51:43 2007 : Debug: >>> LOOKING AT ok) Thu Jul 5 20:51:43 2007 : Debug: ? Evaluating "ok" -> FALSE Thu Jul 5 20:51:43 2007 : Debug: >>> I0 23:ok Thu Jul 5 20:51:43 2007 : Debug: >>> EVALUATE 1 ::):: Thu Jul 5 20:51:43 2007 : Debug: >>> AT EOL2a Thu Jul 5 20:51:43 2007 : Debug: >>> EVALUATE RETURNED ::):: Thu Jul 5 20:51:43 2007 : Debug: >>> AT EOL Thu Jul 5 20:51:43 2007 : Debug: +++? if (ok) -> FALSE Thu Jul 5 20:51:43 2007 : Debug: ++- group pap-with-message returns reject Thu Jul 5 20:51:43 2007 : Debug: auth: Failed to validate the user. Thu Jul 5 20:51:43 2007 : Auth: Login incorrect (rlm_pap: CLEAR TEXT password check failed): [john/bad] (from client localhost port 0) Sending Access-Reject of id 2 to 127.0.0.1 port 53849 Thu Jul 5 20:51:43 2007 : Debug: Finished request 1 state 5
As you can see, the elsif is not even considered. Enrik modules { pap { auto_header = yes } files { usersfile = ${confdir}/users acctusersfile = /dev/null preproxy_usersfile = /dev/null compat = no } } server { authorize { files pap } authenticate { Auth-Type PAP { group pap-with-message { # pap returns either fail or noop or ok or reject pap { # default for ok on authenticate would be to return ok = 2 # default for reject on authenticate would be to return reject = 2 } if (ok) { # the following line is the unintentional workaround # to make the elsif work reject = 2 # update returns updated with priority 1 update reply { Reply-Message := "pap authenticate returned OK" } } elsif (reject) { update reply { Reply-Message := "pap authenticate returned REJECT" } } } # override updated from above thus preserving ok/reject from pap ok = return reject = return } } } john User-Password := '{clear}secret'