- Freeradius-Users - lists.freeradius.org

Freeradius EAP-TLS - every 2nd (even) attempt unsuccessfull
by gracian＠centrum.cz 05 Dec '15

05 Dec '15

Hello all, First, our environment configuration is: FreeRADIUS Version 3.0.4, for host x86_64-redhat-linux-gnu configured for EAP-TLS Cisco WLC 2504 Windows 7/8.1 clients Problem: every 1st (odd) connection to WiFi network is without any problem and part of client's certificate contain "TLS-Client-Cert-Common-Name := 'mib(a)example.com'", which I check using check-eap-tls via part below, is visible: server check-eap-tls { authorize { update config { Auth-Type := Accept } if ("%{TLS-Client-Cert-Common-Name}" =~ /^[A-z.]*(a)example\.ccom$/) { update config { Auth-Type := Accept } } else { update config { Auth-Type := Reject } update reply { Reply-Message := "Your certificate is not valid." } } ... ... ... When I try to disconnect from wifi and connect again with the same client, connection fails. I noticed that debug output differ for successfull and unsuccessfull attempt in part below. --------------------------------------------------------------- Successfull attempt log --------------------------------------------------------------- (1) Found Auth-Type = EAP (1) # Executing group from file /etc/raddb/sites-enabled/default (1) authenticate { (1) eap : Expiring EAP session with state 0x3190079e31930a29 (1) eap : Finished EAP session with state 0x3190079e31930a29 (1) eap : Previous EAP request found for state 0x3190079e31930a29, released from the list (1) eap : Peer sent method TLS (13) (1) eap : EAP TLS (13) (1) eap : Calling eap_tls to process EAP data (1) eap_tls : Authenticate (1) eap_tls : processing EAP-TLS TLS Length 129 (1) eap_tls : Length Included (1) eap_tls : eaptls_verify returned 11 (1) eap_tls : (other): before/accept initialization (1) eap_tls : TLS_accept: before/accept initialization (1) eap_tls : <<< TLS 1.0 Handshake [length 007c], ClientHello SSL: Client requested cached session b76a6cf7f480f98fd8814048c4d959e55dd67c0e180edb92d885511c89beb44e reading pairlist file /var/log/radius/tlscache/b76a6cf7f480f98fd8814048c4d959e55dd67c0e180edb92d885511c89beb44e.vps Couldn't open /var/log/radius/tlscache/b76a6cf7f480f98fd8814048c4d959e55dd67c0e180edb92d885511c89beb44e.vps for reading: No such file or directory SSL: could not load persisted VPs for session b76a6cf7f480f98fd8814048c4d959e55dd67c0e180edb92d885511c89beb44e (1) eap_tls : TLS_accept: SSLv3 read client hello A (1) eap_tls : >>> TLS 1.0 Handshake [length 0059], ServerHello (1) eap_tls : TLS_accept: SSLv3 write server hello A (1) eap_tls : >>> TLS 1.0 Handshake [length 0909], Certificate (1) eap_tls : TLS_accept: SSLv3 write certificate A (1) eap_tls : >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange (1) eap_tls : TLS_accept: SSLv3 write key exchange A (1) eap_tls : >>> TLS 1.0 Handshake [length 00b2], CertificateRequest (1) eap_tls : TLS_accept: SSLv3 write certificate request A (1) eap_tls : TLS_accept: SSLv3 flush data (1) eap_tls : TLS_accept: Need to read more data: SSLv3 read client certificate A In SSL Handshake Phase In SSL Accept mode ------------------------------------------------ Unsuccessfull attempt log ------------------------------------------------ (1) Found Auth-Type = EAP (1) # Executing group from file /etc/raddb/sites-enabled/default (1) authenticate { (1) eap : Expiring EAP session with state 0x55a42e6f55a72377 (1) eap : Finished EAP session with state 0x55a42e6f55a72377 (1) eap : Previous EAP request found for state 0x55a42e6f55a72377, released from the list (1) eap : Peer sent method TLS (13) (1) eap : EAP TLS (13) (1) eap : Calling eap_tls to process EAP data (1) eap_tls : Authenticate (1) eap_tls : processing EAP-TLS TLS Length 129 (1) eap_tls : Length Included (1) eap_tls : eaptls_verify returned 11 (1) eap_tls : (other): before/accept initialization (1) eap_tls : TLS_accept: before/accept initialization (1) eap_tls : <<< TLS 1.0 Handshake [length 007c], ClientHello SSL: Client requested cached session b76a6cf7f480f98fd8814048c4d959e55dd67c0e180edb92d885511c89beb44e reading pairlist file /var/log/radius/tlscache/b76a6cf7f480f98fd8814048c4d959e55dd67c0e180edb92d885511c89beb44e.vps SSL: Successfully restored session b76a6cf7f480f98fd8814048c4d959e55dd67c0e180edb92d885511c89beb44e (1) eap_tls : TLS_accept: SSLv3 read client hello A (1) eap_tls : >>> TLS 1.0 Handshake [length 0051], ServerHello (1) eap_tls : TLS_accept: SSLv3 write server hello A (1) eap_tls : >>> TLS 1.0 ChangeCipherSpec [length 0001] (1) eap_tls : TLS_accept: SSLv3 write change cipher spec A (1) eap_tls : >>> TLS 1.0 Handshake [length 0010], Finished (1) eap_tls : TLS_accept: SSLv3 write finished A (1) eap_tls : TLS_accept: SSLv3 flush data (1) eap_tls : TLS_accept: Need to read more data: SSLv3 read finished A In SSL Handshake Phase In SSL Accept mode I have noticed that during unsuccessfull attempt is in the log this part (2) eap : EAP TLS (13) (2) eap : Calling eap_tls to process EAP data (2) eap_tls : Authenticate (2) eap_tls : processing EAP-TLS TLS Length 59 (2) eap_tls : Length Included and this in successfull log: (2) eap : EAP TLS (13) (2) eap : Calling eap_tls to process EAP data (2) eap_tls : Authenticate (2) eap_tls : processing EAP-TLS (2) eap_tls : Received TLS ACK (2) eap_tls : Received TLS ACK (2) eap_tls : ACK handshake fragment handler (2) eap_tls : eaptls_verify returned 1 (2) eap_tls : eaptls_process returned 13 (2) eap : New EAP session, adding 'State' attribute to reply 0x3190079e33950a29 (2) [eap] = handled Sorry, but I'm new in Freeradius environment and I surely overlook something easy to solve, but in this moment I would kindly ask you, community for a help. It looks to me like a problem with skip some certificate check or caching, but maybe I'm completely wrong. Thank you for you help Gracian

2 8

Disconnect user session on data counter
by Anirudh Malhotra 04 Dec '15

04 Dec '15

Hi everyone, I am new to this list and using freeradius so please bear with me, if I ask anything silly. I am using freeradius 2.1.12, I have successfully configured data counter and user's are not able to start new sessions/authenticate when data limit is reached. But what I am not able to do is disconnect active sessions when the data limit is reached. So if anybody could help me with it. Thanks a lot in advance. BR, Anirudh Malhotra

2 5

Freeradius stops processing and ready to process requests loops
by Greg Antic 04 Dec '15

04 Dec '15

Hi Everyone, We have been running Freeradius 2.x for many months on Ubuntu 14.04 LTS on a few servers. Our Ubuntu boxes were set to auto update and have been doing auto updates for 1-2 years without incident however this weeks updates appear to have broken Freeradius. Freeradius just stopped processing radius requests. When I ran in debug mode the "Ready to process requests." Just keeps looping down the page when radius packets come into the server and nothing is displayed, the radius log remains empty as well. If I run a tcpdump I see the radius packets coming in. We have 4 servers which exhibit the same symptoms. This morning the server auto updated and broke Freeradius again. Below are the packages that are being installed. Has anyone experienced this or could someone advise how else to debug Freeradius to see why it won't process requests as a result of these updates? Start-Date: 2015-12-04 06:38:00 Install: linux-headers-3.13.0-71:amd64 (3.13.0-71.114, automatic), linux-image-extra-3.13.0-71-generic:amd64 (3.13.0-71.114, automatic), linux-image-3.13.0-71-generic:amd64 (3.13.0-71.114, automatic), linux-headers-3.13.0-71-generic:amd64 (3.13.0-71.114, automatic) Upgrade: linux-headers-generic:amd64 (3.13.0.68.74, 3.13.0.71.77), libgnutls-openssl27:amd64 (2.12.23-12ubuntu2.2, 2.12.23-12ubuntu2.3), linux-image-server:amd64 (3.13.0.68.74, 3.13.0.71.77), linux-server:amd64 (3.13.0.68.74, 3.13.0.71.77), linux-headers-server:amd64 (3.13.0.68.74, 3.13.0.71.77), libgnutls26:amd64 (2.12.23-12ubuntu2.2, 2.12.23-12ubuntu2.3), linux-image-generic:amd64 (3.13.0.68.74, 3.13.0.71.77), linux-generic:amd64 (3.13.0.68.74, 3.13.0.71.77) Listening on authentication address 192.168.10.195 port 1812 Listening on accounting address 192.168.10.195 port 1813 Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel Listening on proxy address 192.168.10.195 port 1814 Ready to process requests. Ready to process requests. Ready to process requests. Ready to process requests. Ready to process requests. Ready to process requests. Ready to process requests. Thank you, Greg **************************************************************** The views expressed in this email are, unless otherwise stated, those of the author and not those of Smart Technology Centre or its management. The information in this email is confidential and is intended solely for the addressee. Access to this email by any other party is unauthorised. If you are not the intended recipient, any disclosure, copying, distribution or any action taken or omitted in reliance on this, is prohibited and may be unlawful. Whilst all reasonable steps are taken to ensure the accuracy and integrity of information and data transmitted electronically and to preserve the confidentiality thereof, no liability or responsibility whatsoever is accepted if information or data is, for whatever reason, corrupted or does not reach its intended destination. ***************************************************

3 5

Pre-allocation and association with framedipaddress and username in radius.radippool and effect if entry missing after a successful authentication
by Sophie Loewenthal 03 Dec '15

03 Dec '15

Hi, We preallocate IP addresses with usernames into radius.radippool. Our provisioning script runs every 5 mins, extracting new usernames from our application and then associates a framedipaddress with the new username in the correct pool based on their APN set in our application. The SQL in ippool.conf has been modified, so for example, allocate-clear : has the username = '' removed from the query because we want to keep the username/ipaddress associated. alocat-find: has AND username = '%{User-Name}' Please find a copy of ippool.conf incldued below. This modified SQL should not return an IP address if the username is not associated with a framedipaddress even if the user is in radius.radcheck. How should radius respond if a user authenticates correctly and is in radcheck table, but did not have a username+framedipaddress in radius.radippool? Should I expect to see a message in the logs like: Wed Dec 2 10:37:59 2015 : Info: IP Allocation FAILED from proximus-carli (did proximus.trimbletl.com cli 327711110064161 port 23333 user 344544001217220) Wed Dec 2 10:44:42 2015 : Info: IP Allocation FAILED from vodafone (did vodafone.trimbletl.com cli 31600044278 port 824256 user 344466031488608) Sophie # grep -v ^# ippool.conf allocate-clear = "UPDATE ${ippool_table} /* allocate-clear */ \ SET nasipaddress = '', pool_key = 0, \ callingstationid = '', calledstationid = '', \ expiry_time = NULL, 3GPP_Imsi = '' \ WHERE pool_key = '${pool-key}'" allocate-find = "SELECT framedipaddress FROM ${ippool_table} \ WHERE pool_name = '%{control:Pool-Name}' \ AND username = '%{User-Name}' LIMIT 1" pool-check = "SELECT id FROM ${ippool_table} /* pool-check */ \ WHERE pool_name='%{control:Pool-Name}' LIMIT 1" allocate-update = "UPDATE ${ippool_table} /* allocate-update */ \ SET nasipaddress = '%{NAS-IP-Address}', pool_key = '${pool-key}', \ callingstationid = '%{Calling-Station-Id}', \ expiry_time = NOW() + INTERVAL ${lease-duration} SECOND, \ 3GPP_Imsi = '%{3GPP-IMSI}', calledstationid = '%{Called-Station-Id}' \ WHERE framedipaddress = '%I' AND username = '%{User-Name}'" start-update = "UPDATE ${ippool_table} /* start-update */ \ SET expiry_time = NOW() + INTERVAL ${lease-duration} SECOND \ WHERE nasipaddress = '%{NAS-IP-Address}' AND pool_key = '${pool-key}' \ AND username = '%{User-Name}' \ AND callingstationid = '%{Calling-Station-Id}' \ AND framedipaddress = '%{Framed-IP-Address}'" stop-clear = "UPDATE ${ippool_table} /* stop-clear */ \ SET nasipaddress = '', pool_key = 0, callingstationid = '', \ expiry_time = NULL, 3GPP_Imsi = '', calledstationid = '' \ WHERE nasipaddress = '%{Nas-IP-Address}' AND pool_key = '${pool-key}' \ AND username = '%{User-Name}' \ AND callingstationid = '%{Calling-Station-Id}' \ AND framedipaddress = '%{Framed-IP-Address}'" alive-update = "UPDATE ${ippool_table} /* alive-update */ \ SET expiry_time = NOW() + INTERVAL ${lease-duration} SECOND \ WHERE nasipaddress = '%{Nas-IP-Address}' AND pool_key = '${pool-key}' \ AND username = '%{User-Name}' \ AND callingstationid = '%{Calling-Station-Id}' \ AND framedipaddress = '%{Framed-IP-Address}'" on-clear = "UPDATE ${ippool_table} /* on-clear */ \ SET nasipaddress = '', pool_key = 0, callingstationid = '', \ expiry_time = NULL, 3GPP_Imsi = '', calledstationid = '' \ WHERE nasipaddress = '%{Nas-IP-Address}'" off-clear = "UPDATE ${ippool_table} /* off-clear */ \ SET nasipaddress = '', pool_key = 0, callingstationid = '', \ expiry_time = NULL, 3GPP_Imsi = '', calledstationid = '' \ WHERE nasipaddress = '%{Nas-IP-Address}'"

2 1

RE: finding out which section we're in
by Franks Andy (IT Technical Architecture Manager) 03 Dec '15

03 Dec '15

Thanks Alan and Arran. I'll try this or separate this policies out, whichever works i guess! Thanks again Andy ________________________________________ From: Freeradius-Users [freeradius-users-bounces+andy.franks=sath.nhs.uk(a)lists.freeradius.org] on behalf of Arran Cudbard-Bell [a.cudbardb(a)freeradius.org] Sent: 02 December 2015 18:35 To: FreeRadius users mailing list Subject: Re: finding out which section we're in > On Dec 2, 2015, at 1:04 PM, Franks Andy (IT Technical Architecture Manager) <Andy.Franks(a)sath.nhs.uk> wrote: > > Sorry, realise this request is a bit ambiguous - to state things better, I have policy.d unlang "scripts" which are called both in authorize, accounting and so on (same script), and in the script I want to say if (section==authorize) { stuff } elseif (section==accounting) { stuff } %{Request-Processing-Stage} -Arran

3 2

RE: finding out which section we're in
by Franks Andy (IT Technical Architecture Manager) 02 Dec '15

02 Dec '15

Sorry, realise this request is a bit ambiguous - to state things better, I have policy.d unlang "scripts" which are called both in authorize, accounting and so on (same script), and in the script I want to say if (section==authorize) { stuff } elseif (section==accounting) { stuff } Thanks Andy -----Original Message----- From: Freeradius-Users [mailto:freeradius-users-bounces+andy.franks=sath.nhs.uk@lists.freeradius.org] On Behalf Of Franks Andy (IT Technical Architecture Manager) Sent: 02 December 2015 17:59 To: freeradius-users(a)lists.freeradius.org Subject: finding out which section we're in Hi all, Very quick question hopefully. Is there a way of (in unlang) finding out which section we're in? I have policies called from authorize, accounting etc which do similar things, but it would be nice to do something different based on "section". I've had a look at the runtime variables and dictionaries but can't anything obvious. Thanks Andy - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

3 2

Fwd: authentication Failure
by Ryta Kashemire 02 Dec '15

02 Dec '15

Hello So i have setup freeradius on CentOS Linux release 7.1.1503 (Core) added a client to clients.conf *client (ip-of-client) { secret = (Secret) shortname = (Shortname) nas_type = cisco* and added a user in users *user Auth-Type := System Service-Type = NAS-Prompt-User, cisco-avpair = "shell:priv-lvl=15"* i have user and group set to radiusd in raduisd.conf and radiusd is the owner and group for raddb and all files in the raddb However, when i run a radtest...bellow is my out put *[root@xxx]# radtest username password localhost 0 testing123Sending Access-Request Id 224 from 0.0.0.0:40961 <http://0.0.0.0:40961> to 127.0.0.1:1812 <http://127.0.0.1:1812> User-Name = 'username' User-Password = 'password' NAS-IP-Address = (ip of server host) NAS-Port = 0 Message-Authenticator = 0x00Received Access-Reject Id 224 from 127.0.0.1:1812 <http://127.0.0.1:1812> to 127.0.0.1:40961 <http://127.0.0.1:40961> length 20(0) -: Expected Access-Accept got Access-Reject[root@xxx]# * Could someone please point me in the right direction to were the problem could be.. Awaiting your timely response Regards Ritah

3 4

finding out which section we're in
by Franks Andy (IT Technical Architecture Manager) 02 Dec '15

02 Dec '15

Hi all, Very quick question hopefully. Is there a way of (in unlang) finding out which section we're in? I have policies called from authorize, accounting etc which do similar things, but it would be nice to do something different based on "section". I've had a look at the runtime variables and dictionaries but can't anything obvious. Thanks Andy

1 0

Re: authentication Failure
by Ryta Kashemire 02 Dec '15

02 Dec '15

Also when i run radiusd -x then try to authenticate, i get this error in the radiusd -x output *(0) WARNING: pap : No "known good" password found for the user. Not setting Auth-Type(0) WARNING: pap : Authentication will fail unless a "known good" password is available* Iam very sure about my password but i think it is something to do with the Auth-type i set Patiently waiting for all your feed back :-) Ritah On Wed, Dec 2, 2015 at 5:30 PM, Ryta Kashemire <rytaluv(a)gmail.com> wrote: > Hello > > So i have setup freeradius on CentOS Linux release 7.1.1503 (Core) > > added a client to clients.conf > > > > > *client (ip-of-client) { secret = (Secret) > shortname = (Shortname) nas_type = cisco* > > and added a user in users > > > > *user Auth-Type := System Service-Type = NAS-Prompt-User, cisco-avpair = > "shell:priv-lvl=15"* > > i have user and group set to radiusd in raduisd.conf and radiusd is the > owner and group for raddb and all files in the raddb > > > However, when i run a radtest...bellow is my out put > > > > > > > > > > > > > > *[root@xxx]# radtest username password localhost 0 testing123Sending > Access-Request Id 224 from 0.0.0.0:40961 <http://0.0.0.0:40961> to > 127.0.0.1:1812 <http://127.0.0.1:1812> User-Name = 'username' > User-Password = 'password' NAS-IP-Address = (ip of server > host) NAS-Port = 0 Message-Authenticator = 0x00Received > Access-Reject Id 224 from 127.0.0.1:1812 <http://127.0.0.1:1812> to > 127.0.0.1:40961 <http://127.0.0.1:40961> length 20(0) -: Expected > Access-Accept got Access-Reject[root@xxx]# * > Could someone please point me in the right direction to were the problem > could be.. > > > Awaiting your timely response > > Regards > Ritah > > > > > >

1 0

3.1 and LDAP
by Tynan Young 02 Dec '15

02 Dec '15

Hi, I've got freeradius 3.1 up and running (taken from the git repo on the 25th Nov) on Ubuntu 14.04 and am having weird issues with LDAP. Hoping someone may be able to shed some light. I'm using freeradius for dot1x authentication, both wireless (peap/mschapv2) and wired via NTLM auth. The freeradius LDAP module is used to look up Active Directory group membership and based on membership returns the relevant Tunnel-Private-Group-Id. The issue I'm having is that the LDAP lookup will work most of the time, but will frequently stop working for 5-25 minutes. It will start working again without any changes being made. To isolate LDAP user/server issues I've tried using different user accounts and 2012 AD servers. My freeradius config is pretty stock and I have highlighted what I believe is the the relevent LDAP config below. Please let me know if you need any more configuration to assist. This same LDAP config is working in 3.0.10, but I'm experiencing other unrelated issues (I think) and that is why I am trying 3.1 (these issues seem to be resolved in 3.1 so far). Many thanks! mods-config/files/authorize: DEFAULT Ldap-Group == "CN=test,OU=VLAN-Access,DC=in,DC=testdomain" Tunnel-Medium-Type = 802, Tunnel-Type = VLAN, Tunnel-Private-Group-Id = 10 mods-enabled/ldap: ldap { server = 'dc1.in.testdomain' server = 'dc2.in.testdomain' identity = 'CN=ldapradiusauth,CN=users,DC=in,DC=testdomain' password = 'changeme' base_dn = 'dc=in,dc=testdomain' } user { *SNIP* filter = "(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})" *SNIP* } group { *SNIP* membership_filter = "(member:1.2.840.113556.1.4.1941:=%{control:Ldap-UserDn})" *SNIP* } debug output for when LDAP is not working: Debug: (7) Received Access-Request Id 155 from 192.168.6.253:41795 to 192.168.254.173:1812 via eth0 length 319 Debug: (7) User-Name = "DOMAIN\\testuser" Debug: (7) NAS-IP-Address = 192.168.6.253 Debug: (7) NAS-Port = 0 Debug: (7) NAS-Identifier = "192.168.6.253" Debug: (7) NAS-Port-Type = Wireless-802.11 Debug: (7) Calling-Station-Id = "240A64A07AA3" Debug: (7) Called-Station-Id = "000B869A9037" Debug: (7) Service-Type = Framed-User Debug: (7) Framed-MTU = 1100 Debug: (7) EAP-Message = 0x0208006b190017030100604d9137ede185960c664a078e8b48cc5082037cb862005ef9b5fcd5c382b38ec0169fe33226ba383903ad774f0d68d2570bb96ded52f75b9306047481284bea8329db0f25c65a2e3df1f0ee5e4e774ff8b1bd22e83e8c31e9525a60f8fa16ca2e Debug: (7) State = 0xee38dd6d6038ae2de9d2789435e4c640 Debug: (7) Aruba-Essid-Name = "bandit" Debug: (7) Aruba-Location-Id = "ap1" Debug: (7) Aruba-AP-Group = "grp1" Debug: (7) Aruba-Device-Type = "Win 7" Debug: (7) Message-Authenticator = 0xf0ea95380ec91f06d36168bc3de93a19 Debug: (7) No &session-state attributes to restore Debug: (7) # Executing section authorize from file /etc/freeradius/sites-enabled/default Debug: (7) authorize { Debug: (7) policy filter_username { Debug: (7) if (!&User-Name){ Debug: (7) if (!&User-Name) -> FALSE Debug: (7) if (&User-Name =~ / /){ Debug: No matches Debug: (7) if (&User-Name =~ / /) -> FALSE Debug: (7) if (&User-Name =~ /@.*@/ ){ Debug: No matches Debug: (7) if (&User-Name =~ /@.*@/ ) -> FALSE Debug: (7) if (&User-Name =~ /\.\./ ){ Debug: No matches Debug: (7) if (&User-Name =~ /\.\./ ) -> FALSE Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)){ Debug: No matches Debug: (7) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Debug: (7) if (&User-Name =~ /\.$/){ Debug: No matches Debug: (7) if (&User-Name =~ /\.$/) -> FALSE Debug: (7) if (&User-Name =~ /(a)\./){ Debug: No matches Debug: (7) if (&User-Name =~ /(a)\./) -> FALSE Debug: (7) } # policy filter_username = notfound Debug: (7) modsingle[authorize]: calling preprocess (preprocess) for request 7 Debug: (7) preprocess: Comparing name "DOMAIN\testuser" and check value ".ppp" Debug: (7) preprocess: Comparing name "DOMAIN\testuser" and check value ".slip" Debug: (7) preprocess: Comparing name "DOMAIN\testuser" and check value ".cslip" Debug: (7) modsingle[authorize]: returned from preprocess (preprocess) for request 7 Debug: (7) [preprocess] = ok Debug: (7) modsingle[authorize]: calling chap (chap) for request 7 Debug: (7) modsingle[authorize]: returned from chap (chap) for request 7 Debug: (7) [chap] = noop Debug: (7) modsingle[authorize]: calling mschap (mschap) for request 7 Debug: (7) modsingle[authorize]: returned from mschap (mschap) for request 7 Debug: (7) [mschap] = noop Debug: (7) modsingle[authorize]: calling digest (digest) for request 7 Debug: (7) modsingle[authorize]: returned from digest (digest) for request 7 Debug: (7) [digest] = noop Debug: (7) modsingle[authorize]: calling suffix (realm) for request 7 Debug: (7) suffix: Checking for suffix after "@" Debug: (7) suffix: No '@' in User-Name = "DOMAIN\testuser", looking up realm NULL Debug: (7) suffix: No such realm "NULL" Debug: (7) modsingle[authorize]: returned from suffix (realm) for request 7 Debug: (7) [suffix] = noop Debug: (7) modsingle[authorize]: calling ntdomain (realm) for request 7 Debug: (7) ntdomain: Checking for prefix before "\" Debug: (7) ntdomain: Looking up realm "DOMAIN" for User-Name = "DOMAIN\testuser" Debug: (7) ntdomain: Found realm "DOMAIN" Debug: (7) ntdomain: Adding Stripped-User-Name = "testuser" Debug: (7) ntdomain: Adding Realm = "DOMAIN" Debug: (7) ntdomain: Authentication realm is LOCAL Debug: (7) modsingle[authorize]: returned from ntdomain (realm) for request 7 Debug: (7) [ntdomain] = ok Debug: (7) modsingle[authorize]: calling eap (eap) for request 7 Debug: (7) eap: Peer sent EAP Response (code 2) ID 8 length 107 Debug: (7) eap: Continuing tunnel setup Debug: (7) modsingle[authorize]: returned from eap (eap) for request 7 Debug: (7) [eap] = ok Debug: (7) } # authorize = ok Debug: (7) Found Auth-Type = EAP Debug: (7) # Executing group from file /etc/freeradius/sites-enabled/default Debug: (7) authenticate { Debug: (7) modsingle[authenticate]: calling eap (eap) for request 7 Debug: (7) eap: Got eap_session_t 0x1fd38a0 from request data Debug: (7) eap: Peer sent packet with method EAP PEAP (25) Debug: (7) eap: Calling submodule eap_peap to process data Debug: (7) eap_peap: Continuing EAP-TLS Debug: (7) eap_peap: Peer sent flags -------- Debug: (7) eap_peap: Got complete TLS record (101 bytes) Debug: (7) eap_peap: [eap-tls verify] = ok Debug: (7) eap_peap: [eap-tls process] = ok Debug: (7) eap_peap: Session established. Decoding tunneled attributes Debug: (7) eap_peap: PEAP state phase2 Debug: (7) eap_peap: EAP method MSCHAPv2 (26) Debug: (7) eap_peap: Got tunneled request Debug: (7) eap_peap: EAP-Message = 0x0208004e1a02080049317ef3bc67cb921089a4502f961e0e3e93000000000000000040fbef6cb5343fc997e0c4bee9af0168efc513c085e0344b004652455348564945575c74796e616e74657374 Debug: (7) eap_peap: Setting &request:User-Name from tunnel (protected) identity "DOMAIN\testuser" Debug: (7) eap_peap: Sending tunneled request to inner-tunnel Debug: (7) eap_peap: Adding eap_session_t 0x1fe9a90 to fake request Debug: (7) Added request data 0x1fe9a90 at (nil):1 Debug: (7) Virtual server inner-tunnel received request Debug: (7) EAP-Message = 0x0208004e1a02080049317ef3bc67cb921089a4502f961e0e3e93000000000000000040fbef6cb5343fc997e0c4bee9af0168efc513c085e0344b004652455348564945575c74796e616e74657374 Debug: (7) FreeRADIUS-Proxied-To = 127.0.0.1 Debug: (7) User-Name = "DOMAIN\\testuser" Debug: (7) server inner-tunnel { Debug: (7) No &request:State attribute, can't restore &session-state Debug: (7) # Executing section authorize from file /etc/freeradius/sites-enabled/inner-tunnel Debug: (7) authorize { Debug: (7) modsingle[authorize]: calling chap (chap) for request 7 Debug: (7) modsingle[authorize]: returned from chap (chap) for request 7 Debug: (7) [chap] = noop Debug: (7) modsingle[authorize]: calling mschap (mschap) for request 7 Debug: (7) modsingle[authorize]: returned from mschap (mschap) for request 7 Debug: (7) [mschap] = noop Debug: (7) modsingle[authorize]: calling suffix (realm) for request 7 Debug: (7) suffix: Checking for suffix after "@" Debug: (7) suffix: No '@' in User-Name = "DOMAIN\testuser", looking up realm NULL Debug: (7) suffix: No such realm "NULL" Debug: (7) modsingle[authorize]: returned from suffix (realm) for request 7 Debug: (7) [suffix] = noop Debug: (7) modsingle[authorize]: calling ntdomain (realm) for request 7 Debug: (7) ntdomain: Checking for prefix before "\" Debug: (7) ntdomain: Looking up realm "DOMAIN" for User-Name = "DOMAIN\testuser" Debug: (7) ntdomain: Found realm "DOMAIN" Debug: (7) ntdomain: Adding Stripped-User-Name = "testuser" Debug: (7) ntdomain: Adding Realm = "DOMAIN" Debug: (7) ntdomain: Authentication realm is LOCAL Debug: (7) modsingle[authorize]: returned from ntdomain (realm) for request 7 Debug: (7) [ntdomain] = ok Debug: (7) update control { Debug: (7) &Proxy-To-Realm := LOCAL Debug: (7) } # update control = noop Debug: (7) modsingle[authorize]: calling eap (eap) for request 7 Debug: (7) eap: Peer sent EAP Response (code 2) ID 8 length 78 Debug: (7) eap: Continuing on-going EAP conversation Debug: (7) modsingle[authorize]: returned from eap (eap) for request 7 Debug: (7) [eap] = updated Debug: (7) modsingle[authorize]: calling files (files) for request 7 Debug: (7) files: Searching for user in group "CN=test,OU=VLAN-Access,DC=in,DC=testdomain" Debug: rlm_ldap (ldap): Reserved connection (0) Debug: (7) files: EXPAND TMPL XLAT Debug: (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) Debug: Parsed xlat tree: Debug: literal --> (sAMAccountName= Debug: if { Debug: attribute --> Stripped-User-Name Debug: } Debug: else { Debug: attribute --> User-Name Debug: } Debug: literal --> ) Debug: (7) files: EXPAND (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) Debug: (7) files: --> (sAMAccountName=testuser) Debug: (7) files: EXPAND TMPL LITERAL Debug: (7) files: Performing search in "dc=in,dc=DOMAIN" with filter "(sAMAccountName=testuser)", scope "sub" Debug: (7) files: Waiting for search result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://ForestDnsZones.in.testdomain/DC=ForestDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://in.testdomain/CN=Configuration,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Info: rlm_ldap (ldap): Deleting inviable connection (0) Debug: rlm_ldap: Closing libldap handle 0x1f60190 Info: rlm_ldap (ldap): Need 6 more connections to reach 10 spares Info: rlm_ldap (ldap): Opening additional connection (5), 1 of 28 pending slots used Debug: rlm_ldap (ldap): Connecting to ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389 Debug: rlm_ldap (ldap): New libldap handle 0x1f60190 Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Info: rlm_ldap (ldap): Closing connection (4): Hit idle_timeout, was idle for 135 seconds Debug: rlm_ldap: Closing libldap handle 0x1f9e9d0 Info: rlm_ldap (ldap): Closing connection (3): Hit idle_timeout, was idle for 135 seconds Debug: rlm_ldap: Closing libldap handle 0x1f9e180 Info: rlm_ldap (ldap): Closing connection (2): Hit idle_timeout, was idle for 135 seconds Debug: rlm_ldap (ldap): You probably need to lower "min" Debug: rlm_ldap: Closing libldap handle 0x1f8c9e0 Info: rlm_ldap (ldap): Closing connection (1): Hit idle_timeout, was idle for 135 seconds Debug: rlm_ldap (ldap): You probably need to lower "min" Debug: rlm_ldap: Closing libldap handle 0x1f8bee0 Debug: rlm_ldap (ldap): Reserved connection (5) WARNING: (7) files: Search failed: Timed out while waiting for server to respond. Got new socket, retrying... Debug: (7) files: Waiting for search result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://ForestDnsZones.in.testdomain/DC=ForestDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://in.testdomain/CN=Configuration,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Info: rlm_ldap (ldap): Deleting inviable connection (5) Debug: rlm_ldap: Closing libldap handle 0x1f60190 Info: rlm_ldap (ldap): Need 3 more connections to reach 10 spares Info: rlm_ldap (ldap): Opening additional connection (6), 1 of 32 pending slots used Debug: rlm_ldap (ldap): Connecting to ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389 Debug: rlm_ldap (ldap): New libldap handle 0x1f60190 Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Reserved connection (6) WARNING: (7) files: Search failed: Timed out while waiting for server to respond. Got new socket, retrying... Debug: (7) files: Waiting for search result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://ForestDnsZones.in.testdomain/DC=ForestDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://in.testdomain/CN=Configuration,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Info: rlm_ldap (ldap): Deleting inviable connection (6) Debug: rlm_ldap: Closing libldap handle 0x1f60190 Info: rlm_ldap (ldap): Need 3 more connections to reach 10 spares Info: rlm_ldap (ldap): Opening additional connection (7), 1 of 32 pending slots used Debug: rlm_ldap (ldap): Connecting to ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389 Debug: rlm_ldap (ldap): New libldap handle 0x1f60190 Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Reserved connection (7) WARNING: (7) files: Search failed: Timed out while waiting for server to respond. Got new socket, retrying... Debug: (7) files: Waiting for search result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://ForestDnsZones.in.testdomain/DC=ForestDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://in.testdomain/CN=Configuration,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Info: rlm_ldap (ldap): Deleting inviable connection (7) Debug: rlm_ldap: Closing libldap handle 0x1f60190 Info: rlm_ldap (ldap): Need 3 more connections to reach 10 spares Info: rlm_ldap (ldap): Opening additional connection (8), 1 of 32 pending slots used Debug: rlm_ldap (ldap): Connecting to ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389 Debug: rlm_ldap (ldap): New libldap handle 0x1f60190 Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Reserved connection (8) WARNING: (7) files: Search failed: Timed out while waiting for server to respond. Got new socket, retrying... Debug: (7) files: Waiting for search result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://ForestDnsZones.in.testdomain/DC=ForestDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://in.testdomain/CN=Configuration,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Info: rlm_ldap (ldap): Deleting inviable connection (8) Debug: rlm_ldap: Closing libldap handle 0x1f60190 Info: rlm_ldap (ldap): Need 3 more connections to reach 10 spares Info: rlm_ldap (ldap): Opening additional connection (9), 1 of 32 pending slots used Debug: rlm_ldap (ldap): Connecting to ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389 Debug: rlm_ldap (ldap): New libldap handle 0x1f60190 Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Reserved connection (9) WARNING: (7) files: Search failed: Timed out while waiting for server to respond. Got new socket, retrying... Debug: (7) files: Waiting for search result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://ForestDnsZones.in.testdomain/DC=ForestDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://in.testdomain/CN=Configuration,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Error: rlm_ldap (ldap): Bind with CN=ldapradiusauth,CN=users,DC=in,DC=testdomain to ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389 failed: Timed out while waiting for server to respond Unable to chase referral "ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain" (-5: Timed out) Info: rlm_ldap (ldap): Deleting inviable connection (9) Debug: rlm_ldap: Closing libldap handle 0x1f60190 Info: rlm_ldap (ldap): Need 3 more connections to reach 10 spares Info: rlm_ldap (ldap): Opening additional connection (10), 1 of 32 pending slots used Debug: rlm_ldap (ldap): Connecting to ldap://dc1.in.testdomain:389 ldap://dc2.in.testdomain:389 Debug: rlm_ldap (ldap): New libldap handle 0x1f60190 Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Reserved connection (10) WARNING: (7) files: Search failed: Timed out while waiting for server to respond. Got new socket, retrying... ERROR: (7) files: Hit reconnection limit Debug output for when LDAP is working: Debug: (7) files: EXPAND (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) Debug: (7) files: --> (sAMAccountName=testuser) Debug: (7) files: EXPAND TMPL LITERAL Debug: (7) files: Performing search in "dc=in,dc=DOMAIN" with filter "(sAMAccountName=testuser)", scope "sub" Debug: (7) files: Waiting for search result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://DomainDnsZones.in.testdomain/DC=DomainDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://ForestDnsZones.in.testdomain/DC=ForestDnsZones,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Rebinding to URL ldap://in.testdomain/CN=Configuration,DC=in,DC=testdomain Debug: rlm_ldap (ldap): Waiting for bind result... Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Debug: rlm_ldap (ldap): Bind successful Debug: (7) files: User object found at DN "CN=testuser,OU=users,DC=in,DC=testdomain" Debug: (7) files: Checking for user in group objects Debug: (member:1.2.840.113556.1.4.1941:=%{control:Ldap-UserDn}) Debug: Parsed xlat tree: Debug: literal --> (member:1.2.840.113556.1.4.1941:= Debug: attribute --> LDAP-UserDN Debug: literal --> ) Debug: (7) files: EXPAND (member:1.2.840.113556.1.4.1941:=%{control:Ldap-UserDn}) Debug: (7) files: --> (member:1.2.840.113556.1.4.1941:=CN\3dtestuser\2cOU\3dUsers\2cDC\3din\2cDC\3dtestdomain) Debug: (7) files: Waiting for bind result... Debug: (7) files: Bind successful Debug: (7) files: Performing search in "CN=test,OU=VLAN-Access,DC=in,DC=testdomain" with filter "(member:1.2.840.113556.1.4.1941:=CN\3dtestuser\2cOU\3dUsers\2cDC\3din\2cDC\3dtestdomain", scope "sub" Debug: (7) files: Waiting for search result... Debug: (7) files: User found in group object "CN=test,OU=VLAN-Access,DC=in,DC=testdomain"

3 6