- Freeradius-Users - lists.freeradius.org

Help with Chap and ldap
by P K 06 Dec '13

06 Dec '13

Hi, I'm using openldap and phpldapadmin to create account. The interface allows me to store "clear" password. When I do an ldapsearch commandline, I get base64 password. I don't see an option in phpldapadmin to store "clear-text" type. I've configured freeradius to use ldap and I'm using radtest to test but chap always fails. Is it failing because of base64? It seems to have decoded fine looking at the logs. Why is CHAP failing? Please help. Here's my log. radtest -t chap boris password01 localhost 0 testing123 Sending Access-Request of id 74 to 127.0.0.1 port 1812 User-Name = "boris" CHAP-Password = 0x4ab32d3fc82d3d59528ca82338d3ed40aa NAS-IP-Address = 127.0.1.1 NAS-Port = 0 rad_recv: Access-Reject packet from host 127.0.0.1 port 1812, id=74, length=20 Listening on authentication address * port 1812 Listening on accounting address * port 1813 Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel Listening on proxy address * port 1814 Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 37517, id=74, length=58 User-Name = "boris" CHAP-Password = 0x4ab32d3fc82d3d59528ca82338d3ed40aa NAS-IP-Address = 127.0.1.1 NAS-Port = 0 # Executing section authorize from file /etc/freeradius/sites-enabled/default +- entering group authorize {...} ++[preprocess] returns ok [auth_log] expand: /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/freeradius/radacct/127.0.0.1/auth-detail-20131205 [auth_log] /var/log/freeradius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/127.0.0.1/auth-detail-20131205 [auth_log] expand: %t -> Thu Dec 5 23:31:12 2013 ++[auth_log] returns ok [chap] Setting 'Auth-Type := CHAP' ++[chap] returns ok ++[mschap] returns noop ++[digest] returns noop [suffix] No '@' in User-Name = "boris", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop [eap] No EAP-Message, not doing EAP ++[eap] returns noop [files] expand: %{NAS-IP-Address} -> 127.0.1.1 [files] expand: %{NAS-IP-Address} -> 127.0.1.1 [files] users: Matched entry DEFAULT at line 23 ++[files] returns ok [ldap] performing user authorization for boris [ldap] expand: %{Stripped-User-Name} -> [ldap] ... expanding second conditional [ldap] expand: %{User-Name} -> boris [ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=boris) [ldap] expand: dc=example,dc=int -> dc=example,dc=int [ldap] ldap_get_conn: Checking Id: 0 [ldap] ldap_get_conn: Got Id: 0 [ldap] attempting LDAP reconnection [ldap] (re)connect to 127.0.0.1:389, authentication 0 [ldap] bind as cn=admin,dc=example,dc=int/P0intBlank to 127.0.0.1:389 [ldap] waiting for bind result ... [ldap] Bind was successful [ldap] performing search in dc=example,dc=int, with filter (uid=boris) [ldap] No default NMAS login sequence [ldap] looking for check items in directory... [ldap] userPassword -> Password-With-Header == "password01" [ldap] looking for reply items in directory... [ldap] user boris authorized to use remote access [ldap] ldap_release_conn: Release Id: 0 ++[ldap] returns ok ++[expiration] returns noop ++[logintime] returns noop [pap] Failed to decode Password-With-Header = "password01" [pap] WARNING: Auth-Type already set. Not setting to PAP ++[pap] returns noop Found Auth-Type = CHAP # Executing group from file /etc/freeradius/sites-enabled/default +- entering group CHAP {...} [chap] login attempt by "boris" with CHAP password [chap] Cleartext-Password is required for authentication ++[chap] returns invalid Failed to authenticate the user. Using Post-Auth-Type Reject # Executing group from file /etc/freeradius/sites-enabled/default +- entering group REJECT {...} [attr_filter.access_reject] expand: %{User-Name} -> boris attr_filter: Matched entry DEFAULT at line 11 ++[attr_filter.access_reject] returns updated Delaying reject of request 0 for 1 seconds Going to the next request Waking up in 0.9 seconds. Sending delayed reject for request 0 Sending Access-Reject of id 74 to 127.0.0.1 port 37517 Waking up in 4.9 seconds. Cleaning up request 0 ID 74 with timestamp +22 Ready to process requests. ^C

3 3

rlm_ldap (ldap): Could not start TLS: Connect error
by Hachmer, Tobias 05 Dec '13

05 Dec '13

Hello list, in my further tests with FreeRADIUS v3 (rpmbuild from v3.0.x branch) I have a problem with the ldap module and start_tls. This is definitely working: - Ldap connect with ldap utils (ldapsearch -ZZ and so on) via port 389 with starttls - Ldap connect with FreeRADIUS 2.1.12 via port 389 (start_tls = yes and require_cert = "demand") This is not working: - FR 3 ldap module isn't able to connect to ldap server via port 389 + start_tls=yes - FR debug error: # Loaded module rlm_ldap # Instantiating module "ldap" from file /etc/raddb/mods-enabled/ldap ldap { server = "fqdn" (matches CN in ldap server certificate) port = 389 password = "xxx" identity = "xxx" valuepair_attribute = "radiusVSA" read_clients = yes user { filter = "(&(uid=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=radiusProfile))" scope = "sub" base_dn = "xxx" access_attribute = "radiusAccountStatus" access_positive = yes } group { filter = "(objectClass=groupOfNames)" scope = "sub" base_dn = "xxx" name_attribute = "cn" membership_attribute = "memberOf" membership_filter = "(member=%{control:Ldap-UserDn})" cacheable_name = no cacheable_dn = yes } client { filter = "(objectClass=radiusClient)" scope = "sub" base_dn = "xxx" attribute { identifier = "radiusClientIdentifier" shortname = "radiusClientShortname" nas_type = "radiusClientType" secret = "radiusClientSecret" virtual_server = "radiusClientVirtualServer" require_message_authenticator = "radiusClientRequireMa" } } profile { filter = "(objectclass=radiusObjectProfile)" attribute = "radiusGroupName" default = "xxx" } options { ldap_debug = 597 chase_referrals = yes rebind = yes net_timeout = 1 res_timeout = 20 srv_timelimit = 20 idle = 60 probes = 3 interval = 3 } tls { ca_file = "/etc/raddb/certs/rootca_cert.pem" start_tls = yes require_cert = "demand" (also tested with never, same result) } } accounting { reference = "%{tolower:type.%{Acct-Status-Type}}" } post-auth { reference = "." } rlm_ldap (ldap): Initialising connection pool pool { start = 5 min = 4 max = 10 spare = 3 uses = 0 lifetime = 0 cleanup_delay = 5 idle_timeout = 60 spread = no } rlm_ldap (ldap): Opening additional connection (0) rlm_ldap (ldap): Connecting to fqdn:389 rlm_ldap (ldap): Could not start TLS: Connect error rlm_ldap (ldap): Opening connection failed (0) rlm_ldap (ldap): Removing connection pool /etc/raddb/mods-enabled/ldap[8]: Instantiation failed for module "ldap" - openldap debug log: Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on: Nov 28 11:21:00 radiusv3test slapd[7737]: Nov 28 11:21:00 radiusv3test slapd[7737]: slap_listener_activate(7): Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 busy Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: >>> slap_listener(ldap:///) Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: listen=7, new connection on 16 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on: Nov 28 11:21:00 radiusv3test slapd[7737]: Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: added 16r (active) listener=(nil) Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 2 descriptors Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on: Nov 28 11:21:00 radiusv3test slapd[7737]: 16r Nov 28 11:21:00 radiusv3test slapd[7737]: Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: read active on 16 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16) Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16): got connid=1003 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: connection_read(16): checking for input on id=1003 Nov 28 11:21:00 radiusv3test slapd[7737]: op tag 0x77, time 1385634060 Nov 28 11:21:00 radiusv3test slapd[7737]: conn=1003 op=0 do_extended Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on: Nov 28 11:21:00 radiusv3test slapd[7737]: do_extended: oid=1.3.6.1.4.1.1466.20037 Nov 28 11:21:00 radiusv3test slapd[7737]: Nov 28 11:21:00 radiusv3test slapd[7737]: send_ldap_extended: err=0 oid= len=0 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: send_ldap_response: msgid=1 tag=120 err=0 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on: Nov 28 11:21:00 radiusv3test slapd[7737]: 16r Nov 28 11:21:00 radiusv3test slapd[7737]: Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: read active on 16 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16) Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16): got connid=1003 Nov 28 11:21:00 radiusv3test slapd[7737]: connection_read(16): checking for input on id=1003 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on: Nov 28 11:21:00 radiusv3test slapd[7737]: Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on: Nov 28 11:21:00 radiusv3test slapd[7737]: 16r Nov 28 11:21:00 radiusv3test slapd[7737]: Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: read active on 16 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16) Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16): got connid=1003 Nov 28 11:21:00 radiusv3test slapd[7737]: connection_read(16): checking for input on id=1003 Nov 28 11:21:00 radiusv3test slapd[7737]: connection_read(16): TLS accept failure error=-1 id=1003, closing Nov 28 11:21:00 radiusv3test slapd[7737]: connection_closing: readying conn=1003 sd=16 for close Nov 28 11:21:00 radiusv3test slapd[7737]: connection_close: conn=1003 sd=16 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: removing 16 Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on: Nov 28 11:21:00 radiusv3test slapd[7737]: Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero FreeRADIUS 3: # ldd /usr/sbin/radiusd linux-vdso.so.1 => (0x00007fff8c1ff000) libfreeradius-server.so => /usr/lib64/freeradius/libfreeradius-server.so (0x00007f224b44b000) libfreeradius-radius.so => /usr/lib64/freeradius/libfreeradius-radius.so (0x00007f224b21b000) libfreeradius-eap.so => /usr/lib64/freeradius/libfreeradius-eap.so (0x00007f224b011000) libpcre.so.0 => /lib64/libpcre.so.0 (0x00007f224ade0000) libpcreposix.so.0 => /usr/lib64/libpcreposix.so.0 (0x00007f224abdd000) libtalloc.so.2 => /usr/lib64/libtalloc.so.2 (0x00007f224a9d3000) libcrypto.so.10 => /usr/lib64/libcrypto.so.10 (0x00007f224a639000) libssl.so.10 => /usr/lib64/libssl.so.10 (0x00007f224a3db000) libnsl.so.1 => /lib64/libnsl.so.1 (0x00007f224a1c2000) libresolv.so.2 => /lib64/libresolv.so.2 (0x00007f2249fa8000) libdl.so.2 => /lib64/libdl.so.2 (0x00007f2249da3000) libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f2249b86000) libreadline.so.6 => /lib64/libreadline.so.6 (0x00007f2249943000) libcrypt.so.1 => /lib64/libcrypt.so.1 (0x00007f224970b000) libc.so.6 => /lib64/libc.so.6 (0x00007f2249378000) /lib64/ld-linux-x86-64.so.2 (0x00007f224b66d000) librt.so.1 => /lib64/librt.so.1 (0x00007f2249170000) libz.so.1 => /lib64/libz.so.1 (0x00007f2248f59000) libgssapi_krb5.so.2 => /lib64/libgssapi_krb5.so.2 (0x00007f2248d15000) libkrb5.so.3 => /lib64/libkrb5.so.3 (0x00007f2248a2f000) libcom_err.so.2 => /lib64/libcom_err.so.2 (0x00007f224882a000) libk5crypto.so.3 => /lib64/libk5crypto.so.3 (0x00007f22485fe000) libtinfo.so.5 => /lib64/libtinfo.so.5 (0x00007f22483dd000) libfreebl3.so => /lib64/libfreebl3.so (0x00007f2248170000) libkrb5support.so.0 => /lib64/libkrb5support.so.0 (0x00007f2247f65000) libkeyutils.so.1 => /lib64/libkeyutils.so.1 (0x00007f2247d62000) libselinux.so.1 => /lib64/libselinux.so.1 (0x00007f2247b42000) FreeRADIUS v2.1.12 (default RPM from official CentOS Repo): # ldd /usr/sbin/radiusd linux-vdso.so.1 => (0x00007fffa9980000) libfreeradius-radius-2.1.12.so => /usr/lib64/freeradius/libfreeradius-radius-2.1.12.so (0x00007fb0297b0000) libnsl.so.1 => /lib64/libnsl.so.1 (0x00007fb029591000) libresolv.so.2 => /lib64/libresolv.so.2 (0x00007fb029377000) libpthread.so.0 => /lib64/libpthread.so.0 (0x00007fb02915a000) libcrypt.so.1 => /lib64/libcrypt.so.1 (0x00007fb028f22000) libltdl.so.7 => /usr/lib64/libltdl.so.7 (0x00007fb028d19000) libssl.so.10 => /usr/lib64/libssl.so.10 (0x00007fb028abc000) libcrypto.so.10 => /usr/lib64/libcrypto.so.10 (0x00007fb028721000) libc.so.6 => /lib64/libc.so.6 (0x00007fb02838e000) /lib64/ld-linux-x86-64.so.2 (0x00007fb029c1e000) libfreebl3.so => /lib64/libfreebl3.so (0x00007fb028122000) libdl.so.2 => /lib64/libdl.so.2 (0x00007fb027f1d000) libgssapi_krb5.so.2 => /lib64/libgssapi_krb5.so.2 (0x00007fb027cd9000) libkrb5.so.3 => /lib64/libkrb5.so.3 (0x00007fb0279f3000) libcom_err.so.2 => /lib64/libcom_err.so.2 (0x00007fb0277ee000) libk5crypto.so.3 => /lib64/libk5crypto.so.3 (0x00007fb0275c2000) libz.so.1 => /lib64/libz.so.1 (0x00007fb0273ac000) libkrb5support.so.0 => /lib64/libkrb5support.so.0 (0x00007fb0271a0000) libkeyutils.so.1 => /lib64/libkeyutils.so.1 (0x00007fb026f9d000) libselinux.so.1 => /lib64/libselinux.so.1 (0x00007fb026d7d000) Thanks in advance for any help and please let me know if further information is needed. Kind regards, Tobias Hachmer

3 14

sqltrace.sql
by Sanity Computers 04 Dec '13

04 Dec '13

Ok thanks, the sqltrace feature is handy, it was a display error as the trace looks to be perfect. Now its enabled the display shows the full query. Thanks for the help.

1 0

Crash problem with FR 2.x.x when background databases delay
by Jim Madden 04 Dec '13

04 Dec '13

This note is both a request for assistance in debugging a problem where I’m way out of my depth and a warning that there may be a crash problem lurking in the current 2.x.x code that won’t be visible until a server running it encounters an unusual delay from a back end system. I am not including much detailed diagnostic output because the problem I’m describing doesn’t happen under single threaded debugging and the debugging traces and core dumps that accumulate in multi-threaded mode are gigantic. We have been struggling with an attempted conversion of a Redhat compile-from-source Freeradius 2.2.1 deployment to a compile-from-source version of the latest 2.x.x code. Our very heavily loaded Radius servers provide MAC address and EAP/PEAP/TTLS authentication through a set of very creaky multi-use back-end Mysql servers which can occasionally go non-responsive for many seconds at a time. Ultimately I’d guess that we’ll switch to the FR 3 code but that change requires significant modification to a configuration that has grown up piecemeal over several years, so, in the meantime, we try to keep up with the FR 2 improvements. We’ll also fix our underlying load issues with hardware changes over the next few months, but for now, we have to live with them, so we see the problem described here if we try to advance beyond 2.2.1 code. Our 2.2.1 systems sometimes encounter database response delays that cause them to generate error messages like this Tue Nov 26 15:21:47 2013 : Error: Received conflicting packet from client Campus_WISM port 32770 - ID: 247 due to unfinished request 8533348. Giving up on old request. Tue Nov 26 15:21:50 2013 : Info: WARNING: Module rlm_eap became unblocked for request 8533348 but the servers continue to run. Under 2.2.3, the situation that produces these messages seems likely to generate a follow-on crash after a short period of time. The resulting crash dump shows that the failure is an illegal memory reference in a thread that has a normal seeming stack of modcall routines and code that is referencing a linked structure through a ‘request’ structure that has been damaged; the particular code that fails is not consistent but seems always to be a reference through a ‘request’; inspection of the broken request in the dump shows varying kinds of garbage; to get to the failed code, lots of earlier routines in the call stack would have used the same ‘request’ pointer value to extract data and apparently succeeded in doing so. It is as if some clean-up mechanism in another thread has destroyed the request while it is in use. Other threads in the server seem perfectly happy, waiting for their turn to get a request or to receive data from a database or ntlm_auth process. There seem always to be an error message like the one listed above in the log or log buffers. The crash does not happen under light load on the server and backend systems so that there are no conflicting packets, nor does it happen in unthreaded debug mode apparently because request processing happens sequentially. It does happen with radmin debugging turned on although those are so voluminous that it’s hard to extract useful information about what has happened. It is interesting that, even with backend delays, the crashes do not happen if I change the code in main/event.c that looks like int received_request(rad_listen_t *listener, ... /* * The new request is different from the old one, * but maybe the old is finished. If so, delete * the old one. */ switch (request->child_state) { struct timeval when; default: /* * Special hacks for race conditions. * The reply is encoded, and therefore * likely sent. We received a *new* * packet from the client, likely before * the next line or two of code which * updated the child state. In this * case, just accept the new request. */ if ((request->reply->code != 0) && request->reply->data) { radlog(L_INFO, "WARNING: Allowing fast client %s port %d - ID: %d for recent request %u.", client->shortname, packet->src_port, packet->id, request->number); remove_from_request_hash(request); request = NULL; break; } gettimeofday(&when, NULL); when.tv_sec -= 1; /* * If the cached request was received * within the last second, then we * discard the NEW request instead of the * old one. This will happen ONLY when * the client is severely broken, and is * sending conflicting packets very * quickly. */ if (timercmp(&when, &request->received, <)) { radlog(L_ERR, "Discarding conflicting packet from " "client %s port %d - ID: %d due to recent request %u.", client->shortname, packet->src_port, packet->id, request->number); return 0; } received_conflicting_request(request, client); request = NULL; break; to allow a 300 second leeway instead of the 1 second one so that in effect, received_conflicting_request is never called. I don’t think this particular code or most of its supporting routines have changed much between 2.2.1 and the current 2.x.x. My limited understanding of what’s happening here is that the server has matched a new incoming request with one that’s already in process and calls received_conflicting_request to try to terminate the on-going processing; this can leave an old request that’s waiting for some external event like a database request in process in an active thread but marked to stop when it comes to a sync point. After doing this marking, the code above then goes on to queue the newly arrived request to be worked on. I’m way out of my depth about how these two variants of the same request will be handled beyond this point in the server, but it appears that something has changed about it between the 2.2.1 code that works and the current 2.x.x code that crashes. I wonder if some table look-up or queuing mechanism has changed so that two threads processing these requests get confused about each others data? I will gladly provide more information under direction from the experts. I don’t want to flood the list with endless streams of useless debugging. Jim Madden UCSD Networking jmadden(a)ucsd.edu

3 3

query is been cut short
by Sanity Computers 04 Dec '13

04 Dec '13

Hi all, I'm getting some odd behaviour where a counter is not replying with session-timeout. You can see in the debug below that this accounting update query seems to stop at "AN" rather than "AND nasipaddress = 'NAS-IP-Address'". Sometimes it ends like this also: AND username = 'tes It seems to be cutting off the end of the query. Is this just a debug display/ouput error or an actual problem? ---------------------------- [sql] expand: UPDATE radacct SET framedipaddress = '%{Framed-IP-Address}', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}' -> UPDATE radacct SET framedipaddress = '101.144.24.2', acctsessiontime = '301', acctinputoctets = '0' << 32 | '65806', acctoutputoctets = '0' << 32 | '110397' WHERE acctsessionid = '529e87e100000001' AND username = 'test' AN rlm_sql (sql): Reserving sql socket id: 0 rlm_sql (sql): Released sql socket id: 0 Regards Carl

2 1

Secure auth methods pam_radius
by Bob Probert 03 Dec '13

03 Dec '13

Hello all, I would like to use the PAM Radius module to authenticate Linux servers against my Radius server. I compiled and configured the PAM module, things appear to be working, however I would like to use a more secure authentication method than PAP. Is it possible to force the PAM module to use a more secure method? What does the community endorse as the most secure authentication method for Radius. Thanks! Bob

3 6

decoupled accounting
by Rui Ribeiro 03 Dec '13

03 Dec '13

Hi, I just made the setup of a second RADIUS server, and trying to relay the accounting, preferably with decouple-accounting, because I think it is a more robust configuration. I have already read the freeradius.org pages, a lot of posts, and the virtual server itself; put the decouple-accounting in sites-enabled; managed to intercept the accounting setting up the write_detail.xxxx server, and indeed all the correct accounting goes to /var/log/freeradius/radacct/detail.xxx I also setup on the master side, this secondary server as client in the clients.conf file. However, I am a bit at a loss how to reach the read_detail.xxx server to process the files left by write_detail. Any clues? Regards, Rui Ribeiro

3 2

Acct and Auth on single port
by Jonathan Moore 03 Dec '13

03 Dec '13

Is it possible to have both accounting a authorization requests on a single port? I have a bit of legacy equipment that has a single configuration option for radius port, and appears to send both the account and authorization packets to whatever port is defined there. I have tried created two listen directives both using the same port and listing auth in one and acct in the other, with no success. Is there some method to making this work, or am I stuck with just not getting accounting from this device? Thanks -- Jon M

2 1

sqlippool querries
by Bill Schoolfield 02 Dec '13

02 Dec '13

Hello, I have a couple of things going on. (1) My mysql based ippool is out of sync with the ips actually in use. This is leading to ip conflicts and immediate drops after successful login. (2) take a look at the sql errors. It apparently doesn't like "expiry_time IS NULL" in the update. For (1) how can I get the ippool in sync? Is the only way to reset the radippool table and drop all the connections from the NAS? For (2) is this an error a by product of the immediate disconnect? Is the mysql version of sqlippool known to work. Also for number (2) one problem I see is the schema doesn't account for callingstationid that are this large. I assume I''ll need to change the schema for this. Happy to send config file setup and/or radiusd -X output if it will help. Though the setup is very basic. Bill > tail -f /var/log/radius/radius.log > Mon Dec 2 14:21:40 2013 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 > Mon Dec 2 14:21:40 2013 : Info: rlm_sql (sql): Connected new DB handle, #4 > Mon Dec 2 14:21:40 2013 : Info: Loaded virtual server <default> > Mon Dec 2 14:21:40 2013 : Info: Ready to process requests. > Mon Dec 2 14:28:24 2013 : Auth: Login OK: [abraham1078(a)epsiton.com] (from client ERX2 port 21068 cli GigabitEthernet 3/0/6.3220146:322-146#587449101#801 GE1 TOROON4415W-TOROON4425W##pppoe 68:15:90:3e:0b:81#) > Mon Dec 2 14:28:24 2013 : Error: sqlippool_command: database query error in: 'UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time IS NULL WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '204.101.13.1'' > Mon Dec 2 14:28:24 2013 : Error: rlm_radutmp: Logout for NAS ERX2 port 21068, but no Login record > Mon Dec 2 14:28:24 2013 : Error: sqlippool_command: database query error in: 'UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time IS NULL WHERE nasipaddress = '204.101.13.1' AND pool_key = '21068' AND username = 'abraham1078(a)epsiton.com' AND callingstationid = 'GigabitEthernet 3/0/6.3220146:322-146=23587449101=23801 GE1 TOROON4415W-TOROON4425W=23=23pppoe 68:15:90:3e:0b:81=23' AND framedipaddress = ''' > Mon Dec 2 14:28:24 2013 : Info: Released IP (did cli GigabitEthernet 3/0/6.3220146:322-146#587449101#801 GE1 TOROON4415W-TOROON4425W##pppoe 68:15:90:3e:0b:81# user abraham1078(a)epsiton.com) > Mon Dec 2 14:28:24 2013 : Info: [sql] stop packet with zero session length. [user 'abraham1078(a)epsiton.com', nas '204.101.13.1'] > Mon Dec 2 14:40:57 2013 : Auth: Login OK: [abraham1078(a)epsiton.com] (from client ERX2 port 21070 cli GigabitEthernet 3/0/6.3220146:322-146#587449101#801 GE1 TOROON4415W-TOROON4425W##pppoe 68:15:90:3e:0b:81#) query error here: > Mon Dec 2 14:40:57 2013 : Error: sqlippool_command: database query error in: 'UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time IS NULL WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '204.101.13.1'' > Mon Dec 2 14:40:57 2013 : Error: rlm_radutmp: Logout for NAS ERX2 port 21070, but no Login record > Mon Dec 2 14:40:57 2013 : Error: sqlippool_command: database query error in: 'UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time IS NULL WHERE nasipaddress = '204.101.13.1' AND pool_key = '21070' AND username = 'abraham1078(a)epsiton.com' AND callingstationid = 'GigabitEthernet 3/0/6.3220146:322-146=23587449101=23801 GE1 TOROON4415W-TOROON4425W=23=23pppoe 68:15:90:3e:0b:81=23' AND framedipaddress = ''' > Mon Dec 2 14:40:57 2013 : Info: Released IP (did cli GigabitEthernet 3/0/6.3220146:322-146#587449101#801 GE1 TOROON4415W-TOROON4425W##pppoe 68:15:90:3e:0b:81# user abraham1078(a)epsiton.com) > Mon Dec 2 14:40:57 2013 : Info: [sql] stop packet with zero session length. [user 'abraham1078(a)epsiton.com', nas '204.101.13.1']

2 3

LDAP Module : basedn empty -> error
by Dominique Fournier 02 Dec '13

02 Dec '13

Hi I try to connect my Freeradius to a Zimbra LDAP server with multidomain. In Zimbra, the LDAP tree is something like : "ou=people,dc=domain,dc=tld". I have some domains in ".fr" and some other in ".org". If I configure with the basedn = "dc=fr", Freeradius works well for all the domains in ".fr". But if I try to allow all my domains (with a basedn=""), Freeradius don't accept to authenticate the users. In the logs, when there is a reject, I can see : [ldap-inner-tunnel] performing user authorization for XXXXX [ldap-inner-tunnel] expand: (mail=%{User-Name}) -> (mail=XXXXX.fr) [ldap-inner-tunnel] expand: -> [ldap-inner-tunnel] unable to create basedn. ++[ldap-inner-tunnel] returns invalid Invalid user: [XXXXX.fr] (from client localhost port 0 via TLS tunnel) I found a topic in the list http://freeradius.1045715.n5.nabble.com/Sending-null-BaseDN-td5716006.html in 2012, but there is no solution. I am on a Debian stable Freeradius 2.1.12 Thanks a lot. Dom

3 10