August 2012 - Freeradius-Users - lists.freeradius.org

Detailed Logging freeradius Request Packets
by Jean-Francois Mousinho 28 Oct '19

28 Oct '19

Hi, I've tried to find a way of detail logging the packets sent by freeradius to the client in the authentication phase but didn't found a way of doing it. Maybe I've not looked correctly so I'm asking if it's actually possible? I was able to log detailed packets sent by the client (Response packets) but not the ones sent by freeradius to the client (except accounting and proxied ones). Thanks for your time. Jean-François Mousinho

4 6

user-group for rejected users
by Fabricio Viana 21 Mar '17

21 Mar '17

Hello! Let´s suppose the following situations: 1) User exists but the password is wrong 2) User does not exist In both cases the answer is REJECT. It happens that certain hardware is making endless attempts that eventually saturating the server. - It is possible to cause the server, instead of rejecting the users, accept the login but responds ACCEPT with "framed-pool = pool-block" ? or/and - Is there any way to put REJECT users in a given group by default? Thanks! Fabricio

3 3

Huntgroup Checking
by simonm123 28 Feb '13

28 Feb '13

Am new to freeradius but have it mainly set up just fine. It's a fantastic tool and I'm enjoying using it :) Just one thing I'm struggling with is the huntgroups. I've followed the wiki to the letter and can see the server checking in the debug log. What I basically want to do is restrict users to certain networks, as per the wiki. If their huntgroup-name matches their huntgroup based on nasip, they can get online, otherwise they're rejected. I've put Huntgroup-Name = NetworkA in my radgroupcheck folder. In my radhuntgroup table, I have the nasip and groupname = NetworkA Then, in the authorize section of my default host, I put: update request { Huntgroup-Name := "%{sql:SELECT `groupname` FROM `radhuntgroup` WHERE nasipaddress='%{NAS-IP-Address}'}" } if (Huntgroup-Name == ''){ reject } All as per the tutorial In my debug log, if there is no match by IP, Huntgroup-Name is blank and the user is rejected. However, if the nasip address match but the name is different, the user is still allowed on. Do I need a more advanced query in the if section and if so,could you please advise what it should be Simon -- View this message in context: http://freeradius.1045715.n5.nabble.com/Huntgroup-Checking-tp4950385p495038… Sent from the FreeRadius - User mailing list archive at Nabble.com.

5 6

Dialup Admin
by Shawky Skaff 24 Jan '13

24 Jan '13

I was wondering if you can point me in the right direction for a couple of issues that I'm having - When I view a session of a user, it says user "bla" has 0 open session, which it weird because the user is connected. Where does radius get this info from? Is there anything that I need to change to fix it? - Is radkill still used? Is there anywhere I can obtain this from, the ftp link in the wiki times out after a while

2 2

Kerberos - Radius does not get password
by Jörg Herzinger 28 Dec '12

28 Dec '12

Hi, Radius has been bugging me now for over a week and I just can't get it working with Kerberos over WLan. I have been trying around a lot but in the end I purged the freeradius packages and restarted from scratch with default config (on Debian squeeze). All I did was adding a client in clients.conf client 192.168.0.0/16 { secret = averysecretsecret } adding two entries in users.conf testing Cleartext-Password := "pass" DEFAULT Auth-Type = Kerberos and adding Kerberos to authenticate in default and inner-tunnel right after PAP: Auth-Type Kerberos { krb5 } and I configured the Kerberos module. Now when testing with radtest both (kerberos and testing from files) work fine root@donauauen42 ~ # radtest testing pass radius 1 averysecretsecret Sending Access-Request of id 166 to 192.168.43.118 port 1812 User-Name = "testing" User-Password = "pass" NAS-IP-Address = 192.168.42.42 NAS-Port = 1 rad_recv: Access-Accept packet from host 192.168.43.118 port 1812, id=166, length=20 root@donauauen42 ~ # radtest pink.funk-greene XXXXX radius 1 averysecretsecret Sending Access-Request of id 60 to 192.168.43.118 port 1812 User-Name = "pink.funk-greene" User-Password = "XXXXX" NAS-IP-Address = 192.168.42.42 NAS-Port = 1 rad_recv: Access-Accept packet from host 192.168.43.118 port 1812, id=60, length=20 But when testing via WiFi just my testing user works, while my Kerberos users won't work. Not working Kerberos debug log: http://pastie.org/3890159 Vs. working plain users file log: http://pastie.org/3890167 Any help is appreceated. Thanks a lot... -- Jörg Herzinger - EDV Team GLOBAL 2000 - Friends of the Earth Austria Neustiftgasse 36, A-1070 Wien tel +43-699-14200030 Dieses Mail wurde mit Oekostrom und Opensource Software erstellt.

4 3

Re: rlm_perl authentication override
by Henry 20 Nov '12

20 Nov '12

Quoting tnt(a)kalik.net: >>>> Is there a way to change the reply from Access-Reject, to Access-Accept? >>>> > > Change freeradius.internal attribute Packet-Type in Post-Auth-Type Reject > section. Changing freeradius.internal Packet-Type from Access-Reject to Access-Accept would affect ALL logins - even logins which *should* be rejected. I'm referring to changing Access-Reject to Access-Accept under certain circumstances only -- not globally for all logins. ...or am I misunderstanding what you're suggesting? Thanks Henry

5 13

New attribute on old freeradius server
by Tiago 23 Oct '12

23 Oct '12

Hello everyone, I'm trying to implement an new radreply attribute on an old freeradius 1.x production server that should be replaced on the next days. I've set a user attribute on my mysql database - table radreply like: Shape = 1 I've added that new attribute on my dictionary file /etc/freeradius/dictionary (ubuntu server) like: ..... ...... ATTRIBUTE Shape 86 integer I'm doing some radtests and I'm getting this: Thu Aug 2 14:43:49 2012 : Error: rlm_sql: Failed to create the pair: Unknown attribute "Shape" Thu Aug 2 14:43:49 2012 : Error: rlm_sql (sql): Error getting data from database Thu Aug 2 14:43:49 2012 : Auth: Login OK: [user] (from client pppoe02 port 0) Where else should I look for? Kindly regards, Tiago

2 5

Using ldap_xlat in unlang with Chars not allowed in an ldap search
by Daniel Finger 01 Oct '12

01 Oct '12

Hi! I have a Problem using the ldap Module to search in the ldap Tree for a specific Attribute Containing a (. I am using FreeRadius (2.1.12) for 802.1X Authentification (EAP-TLS) which is working fine. After successful EAP Authentication, I want to check if the User has an Entry in the LDAP: During authenticate (I just changed a bit of formattig to have it readable here): Auth-Type eap { eap # Some Code to react to EAP Auth Failures if ( "%{TLS-Client-Cert-Common-Name}" != "" ) { update control { Tmp-String-1 = "%{ldap_WLAN_auth: ldap:///cn=UserAccounts,dc=DE?cn?sub? ( & (CommonName=%{TLS-Client-Cert-Common-Name}) (allowedSSID=%{Aruba-Essid-Name}) )}" } if ("%{control:Tmp-String-1}" == "") { update control { Auth-Type := "Reject" } update reply { Reply-Message = "The user %{User-Name} is not known or allowed to access the SSID %{Aruba-Essid- Name}" } reject } Now the {TLS-Client-Cert-Common-Name} contains a ( and a ) which leads to a bad search filter: |Debug: [ldap_WLAN_auth] - ldap_xlat |Info: expand: ldap:///cn=UserAccounts,dc=NI-NGN,dc=DE?cn?sub?(&(CommonName=%{TLS-Client-Cert-Common-Name})(allowedSSID=%{Aruba-Essid-Name})) -> ldap:///cn=UserAccounts,dc=DE?cn?sub?(&(CommonName=Testuser(10) Daniel)(allowedSSID=ssid-data)) |Debug: [ldap_WLAN_auth] ldap_get_conn: Checking Id: 0 |Debug: [ldap_WLAN_auth] ldap_get_conn: Got Id: 0 |Debug: [ldap_WLAN_auth] performing search in cn=UserAccounts,dc=DE, with filter (&(CommonName=Testuser(10) Daniel)(allowedSSID=ssid-data)) |ldap_search() failed: Bad search filter: (&(CommonName=Testuser(10) Daniel)(allowedSSID=ssid-data)) |Debug: [ldap_WLAN_auth] Search returned error |Debug: [ldap_WLAN_auth] ldap_release_conn: Release Id: 0 |Info: expand: %{ldap_WLAN_auth:ldap:///cn=UserAccounts,dc=DE?cn?sub?(&(CommonName=%{TLS-Client-Cert-Common-Name})(allowedSSID=%{Aruba-Essid-Name}))} -> If I have searched correctly it should work if I rewrite the Attribute with \28 for ( and \29 for ) (as ascii string, not escaped :-)) As it seems the rewrite Module is not the solution as i could not get it to do this :-) It works as I expected it to do if the CommonName does not contain the Parentheses. Any Ideas to work around these Parentheses? Preferably using any Char allowed in the Common Name, as i expect it to contain Umlauts or an & Char. Greetings, Daniel

2 3

request_dequeue problems (recent 3.0, when home-server stalls)
by Brian Julin 20 Sep '12

20 Sep '12

I'm currently hunting a problem that causes a recent checkout of FR3.0 to abort but which does not seem to be affecting an older revision (April 8th or so) of FR3.0 on another box. I do have a couple small in-house patches applied but they should probably not be relevant. The issue seems to happen when a home-server does not respond to a request, and then FR re-enqueues the request as a retransmit. The request then gets dequeued again, and at that point fails a REQUEST_MAGIC assert. That is, if I am reading the logs correctly... Logs are included, with a few added printfs thrown in. Anyone have any suggestions for good commits to bisect at? rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=2 63 request_enqueue 0x13d5220 Thread 1 got semaphore request_dequeue prequest before 0x13c0a00->(nil) Thread 3 got semaphore request_dequeue found request 0x13d5220 Thread 2 got semaphore request_dequeue prequest after 0x13c0a00->0x13d5220 request_dequeue prequest before 0x13c0b80->(nil) Thread 4 got semaphore Thread 2 exiting... Thread 1 handling request 258, (130 handled so far) request_dequeue prequest before 0x13c0e80->(nil) Thread 4 exiting... [... request dump ...] request_dequeue prequest before 0x13c0d00->(nil) Thread 3 exiting... (258) <thread> : # Executing section authorize from file /etc/raddb/eduroam_sp.c onf [... bunch of unlang/realm chatter ...] Sending Access-Request of id 38 to [... request dump ...] (258) Proxying request to home server ... Thread 1 exiting... Waking up in 0.2 seconds. request_enqueue 0x13d5220 Waking up in 0.2 seconds. Waking up in 0.4 seconds. Waking up in 0.7 seconds. Waking up in 1.1 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263 Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258 Waking up in 0.9 seconds. Waking up in 1.4 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263 Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258 Waking up in 0.4 seconds. (255) Cleaning up request packet ID 198 with timestamp +6868 Waking up in 0.2 seconds. (256) Cleaning up request packet ID 166 with timestamp +6868 Waking up in 0.2 seconds. (257) Cleaning up request packet ID 128 with timestamp +6868 Waking up in 2.1 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263 Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258 Waking up in 1.1 seconds. Waking up in 3.7 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263 Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258 Waking up in 2.9 seconds. rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=104, length=263 Discarding duplicate request from client EDUROAM_OUT port 57940 - ID: 104 due to unfinished request 258 Waking up in 0.9 seconds. Waking up in 5.6 seconds. Waking up in 8.5 seconds. Waking up in 12.8 seconds. Waking up in 19.2 seconds. Waking up in 28.8 seconds. (258) <queue> : Cleaning up request packet ID 104 with timestamp +6869 Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=125, length=254 request_enqueue 0x13c2080 Deleting thread 1 Deleting thread 2 Deleting thread 3 Deleting thread 4 Waking up in 0.3 seconds. Waking up in 0.4 seconds. Waking up in 0.7 seconds. Waking up in 1.1 seconds. Waking up in 1.6 seconds. Waking up in 2.5 seconds. Waking up in 3.7 seconds. Waking up in 5.6 seconds. Waking up in 8.5 seconds. Waking up in 12.8 seconds. Waking up in 19.2 seconds. Waking up in 28.8 seconds. (259) <queue> : Cleaning up request packet ID 125 with timestamp +10992 Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 57940, id=228, length=254 request_enqueue 0x13c2080 Threads: total/active/spare threads = 0/0/0 Threads: Spawning 4 spares Thread spawned new child 5. Total threads in pool: 1 Thread spawned new child 6. Total threads in pool: 2 Thread spawned new child 7. Total threads in pool: 3 Thread 5 waiting to be assigned a request Thread 5 got semaphore request_dequeue prequest before 0x13c0e80->(nil) request_dequeue found request 0x13d5220 ASSERT FAILED threads.c[468]: request->magic == REQUEST_MAGIC Thread spawned new child 8. Total threads in pool: 4 Thread 7 waiting to be assigned a request Thread 6 waiting to be assigned a request Thread 6 got semaphore Thread 7 got semaphore

3 4

PEAP failure problem
by Ana Gallardo Gómez 07 Sep '12

07 Sep '12

Hello, I'm using FreeRADIUS version 2.1.10 I would like to return diferent values of a personal atribute (Codigo-Reject) in a Access-Reject. I would like to do this in PEAPv0, EAP-TTLS-PAP and EAP-TTLS-MsCHAPv2 With my configuration I can return Codigo-Reject in EAP-TTLS-PAP and EAP-TTLS-MsCHAPv2 but I can't in PEAP. My config: cat /etc/freeradius/users ... DEFAULT Intentos-Reject > 10, Auth-Type := Reject Reply-Message += "NUMERO DE INTENTOS FALLIDOS (%{Intentos-Reject}) EXCEDIDO PARA %{%{Stripped-User-Name}:-%{User-Name}}", Codigo-Reject = Cuenta-Bloqueada-Intentos-Reject, Fall-Through = yes ... cat /etc/freeradius/sites-enabled/e server e { authorize { auth_log suffix files eap { ok = return } } authenticate { eap } post-auth { ... Post-Auth-Type REJECT { update reply { Codigo-Reject = Credenciales-Erroneas } sql{ fail=1 } if (fail) { ... } } #server e cat /etc/freeradius/sites-enabled/inner-tunnel server inner-tunnel { authorize { update outer.request { User-Name := "%u" } mschap auth_log suffix update control { Proxy-To-Realm := LOCAL } eap { ok = return } if ("%{Realm}"=='test.es'){ update request { Intentos-Reject = "%{sql:SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject'}" Intentos-Reject += "%{sqlradiusba:SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject'}" } } files if ("%{control:Auth-Type}" == 'Reject') { update outer.reply { Codigo-Reject = "%{reply:Codigo-Reject}" } reject } ... pap } authenticate { Auth-Type PAP { pap } Auth-Type MS-CHAP { mschap } eap } post-auth { sql{ fail=1 } if (fail) { ... } reply_log } } # -inner-tunnel server block LOG EAP-TTLS-PAP: Fri Aug 24 13:37:07 2012 : Info: [ttls] Got tunneled request User-Name = "prueba(a)test.es" User-Password = "530" FreeRADIUS-Proxied-To = 127.0.0.1 Fri Aug 24 13:37:07 2012 : Info: [ttls] Sending tunneled request User-Name = "prueba(a)test.es" User-Password = "530" FreeRADIUS-Proxied-To = 127.0.0.1 NAS-IP-Address = 127.0.0.1 Calling-Station-Id = "02:00:00:00:00:01" Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 11Mbps 802.11b" server inner-tunnel { Fri Aug 24 13:37:07 2012 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-tunnel Fri Aug 24 13:37:07 2012 : Info: +- entering group authorize {...} Fri Aug 24 13:37:07 2012 : Info: expand: %u -> prueba(a)test.es Fri Aug 24 13:37:07 2012 : Info: ++[outer.request] returns notfound Fri Aug 24 13:37:07 2012 : Info: ++[mschap] returns noop Fri Aug 24 13:37:07 2012 : Info: [auth_log] expand: /var/log/freeradius/radacct/%Y/%m/%d/%{Client-IP-Address}-auth-detail-%Y%m%d -> /var/log/freeradius/radacct/2012/08/24/1.2.3.4-auth-detail-20120824 Fri Aug 24 13:37:07 2012 : Info: [auth_log] /var/log/freeradius/radacct/%Y/%m/%d/%{Client-IP-Address}-auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/2012/08/24/1.2.3.4-auth-detail-20120824 Fri Aug 24 13:37:07 2012 : Info: [auth_log] expand: %t -> Fri Aug 24 13:37:07 2012 Fri Aug 24 13:37:07 2012 : Info: ++[auth_log] returns ok Fri Aug 24 13:37:07 2012 : Info: [suffix] Looking up realm "test.es" for User-Name = "prueba(a)test.es" Fri Aug 24 13:37:07 2012 : Info: [suffix] Found realm "test.es" Fri Aug 24 13:37:07 2012 : Info: [suffix] Adding Stripped-User-Name = "prueba" Fri Aug 24 13:37:07 2012 : Info: [suffix] Adding Realm = "test.es" Fri Aug 24 13:37:07 2012 : Info: [suffix] Authentication realm is LOCAL. Fri Aug 24 13:37:07 2012 : Info: ++[suffix] returns ok Fri Aug 24 13:37:07 2012 : Info: ++[control] returns ok Fri Aug 24 13:37:07 2012 : Info: [eap] No EAP-Message, not doing EAP Fri Aug 24 13:37:07 2012 : Info: ++[eap] returns noop Fri Aug 24 13:37:07 2012 : Info: ++? if ("%{Realm}"=='test.es') Fri Aug 24 13:37:07 2012 : Info: expand: %{Realm} -> test.es Fri Aug 24 13:37:07 2012 : Info: ?? Evaluating ("%{Realm}"=='test.es') -> TRUE Fri Aug 24 13:37:07 2012 : Info: ++? if ("%{Realm}"=='test.es') -> TRUE Fri Aug 24 13:37:07 2012 : Info: ++- entering if ("%{Realm}"=='test.es') {...} Fri Aug 24 13:37:07 2012 : Info: sql_xlat Fri Aug 24 13:37:07 2012 : Info: expand: %{Stripped-User-Name} -> prueba Fri Aug 24 13:37:07 2012 : Info: expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> prueba Fri Aug 24 13:37:07 2012 : Info: sql_set_user escaped user --> 'prueba' Fri Aug 24 13:37:07 2012 : Info: expand: SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject' -> SELECT COUNT(*) from radpostauth WHERE username = 'prueba(a)test.es' AND authdate > CURRENT_DATE and reply = 'Access-Reject' Fri Aug 24 13:37:07 2012 : Debug: rlm_sql (sql): Reserving sql socket id: 3 Fri Aug 24 13:37:07 2012 : Info: sql_xlat finished Fri Aug 24 13:37:07 2012 : Debug: rlm_sql (sql): Released sql socket id: 3 Fri Aug 24 13:37:07 2012 : Info: expand: %{sql:SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject'} -> 26 Fri Aug 24 13:37:07 2012 : Info: sql_xlat Fri Aug 24 13:37:07 2012 : Info: expand: %{Stripped-User-Name} -> prueba Fri Aug 24 13:37:07 2012 : Info: expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> prueba Fri Aug 24 13:37:07 2012 : Info: sql_set_user escaped user --> 'prueba' Fri Aug 24 13:37:07 2012 : Info: expand: SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject' -> SELECT COUNT(*) from radpostauth WHERE username = 'prueba(a)test.es' AND authdate > CURRENT_DATE and reply = 'Access-Reject' Fri Aug 24 13:37:07 2012 : Debug: rlm_sql (sqlradiusba): Reserving sql socket id: 4 Fri Aug 24 13:37:08 2012 : Info: sql_xlat finished Fri Aug 24 13:37:08 2012 : Debug: rlm_sql (sqlradiusba): Released sql socket id: 4 Fri Aug 24 13:37:08 2012 : Info: expand: %{sqlradiusba:SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject'} -> 0 Fri Aug 24 13:37:08 2012 : Info: +++[request] returns noop Fri Aug 24 13:37:08 2012 : Info: ++- if ("%{Realm}"=='test.es') returns noop Fri Aug 24 13:37:08 2012 : Info: [files] users: Matched entry DEFAULT at line 29 Fri Aug 24 13:37:08 2012 : Info: [files] expand: %{Stripped-User-Name} -> prueba Fri Aug 24 13:37:08 2012 : Info: [files] expand: NUMERO DE INTENTOS FALLIDOS (%{Intentos-Reject}) EXCEDIDO PARA %{%{Stripped-User-Name}:-%{User-Name}} -> NUMERO DE INTENTOS FALLIDOS (26) EXCEDIDO PARA prueba Fri Aug 24 13:37:08 2012 : Info: [files] users: Matched entry DEFAULT at line 36 Fri Aug 24 13:37:08 2012 : Info: ++[files] returns ok Fri Aug 24 13:37:08 2012 : Info: ++? if ("%{control:Auth-Type}" == 'Reject') Fri Aug 24 13:37:08 2012 : Info: expand: %{control:Auth-Type} -> Reject Fri Aug 24 13:37:08 2012 : Info: ? Evaluating ("%{control:Auth-Type}" == 'Reject') -> TRUE Fri Aug 24 13:37:08 2012 : Info: ++? if ("%{control:Auth-Type}" == 'Reject') -> TRUE Fri Aug 24 13:37:08 2012 : Info: ++- entering if ("%{control:Auth-Type}" == 'Reject') {...} Fri Aug 24 13:37:08 2012 : Info: expand: %{reply:Codigo-Reject} -> Cuenta-Bloqueada-Intentos-Reject Fri Aug 24 13:37:08 2012 : Info: +++[outer.reply] returns ok Fri Aug 24 13:37:08 2012 : Info: +++[reject] returns reject Fri Aug 24 13:37:08 2012 : Info: ++- if ("%{control:Auth-Type}" == 'Reject') returns reject } # server inner-tunnel Fri Aug 24 13:37:08 2012 : Info: [ttls] Got tunneled reply code 3 Reply-Message += "NUMERO DE INTENTOS FALLIDOS (26) EXCEDIDO PARA prueba" Codigo-Reject = Cuenta-Bloqueada-Intentos-Reject Fri Aug 24 13:37:08 2012 : Info: [ttls] Got tunneled Access-Reject Fri Aug 24 13:37:08 2012 : Info: [eap] Handler failed in EAP/ttls Fri Aug 24 13:37:08 2012 : Info: [eap] Failed in EAP select Fri Aug 24 13:37:08 2012 : Info: ++[eap] returns invalid Fri Aug 24 13:37:08 2012 : Info: Failed to authenticate the user. Fri Aug 24 13:37:08 2012 : Info: } # server Fri Aug 24 13:37:08 2012 : Info: Using Post-Auth-Type Reject Fri Aug 24 13:37:08 2012 : Info: # Executing group from file /etc/freeradius/sites-enabled/ Fri Aug 24 13:37:08 2012 : Info: +- entering group REJECT {...} Fri Aug 24 13:37:08 2012 : Info: ++[reply] returns noop Fri Aug 24 13:37:08 2012 : Info: [sql] expand: %{Stripped-User-Name} -> Fri Aug 24 13:37:08 2012 : Info: [sql] ... expanding second conditional Fri Aug 24 13:37:08 2012 : Info: [sql] expand: %{User-Name} -> prueba(a)test.es Fri Aug 24 13:37:08 2012 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> prueba(a)test.es Fri Aug 24 13:37:08 2012 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> prueba(a)test.es Fri Aug 24 13:37:08 2012 : Info: [sql] sql_set_user escaped user --> ' prueba(a)test.es' Fri Aug 24 13:37:08 2012 : Info: [sql] expand: INSERT INTO radpostauth (username, mac, client, reply, authdate,codreject,radauth) VALUES ( LOWER('%{User-Name}'), LOWER('%i'), '%C', '%{reply:Packet-Type}', NOW(), '%{reply:Codigo-Reject}','radiuscc') -> INSERT INTO radpostauth (username, mac, client, reply, authdate,codreject,radauth) VALUES ( LOWER('prueba(a)test.es'), LOWER('02:00:00:00:00:01'), 'CAU1', 'Access-Reject', NOW(), 'Cuenta-Bloqueada-Intentos-Reject','radiuscc') Fri Aug 24 13:37:08 2012 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, mac, client, reply, authdate,codreject,radauth) VALUES ( LOWER('prueba(a)test.es'), LOWER('02:00:00:00:00:01'), 'CAU1', 'Access-Reject', NOW(), 'Cuenta-Bloqueada-Intentos-Reject','radiuscc') Fri Aug 24 13:37:08 2012 : Debug: rlm_sql (sql): Reserving sql socket id: 2 Fri Aug 24 13:37:08 2012 : Debug: rlm_sql (sql): Released sql socket id: 2 Fri Aug 24 13:37:08 2012 : Info: ++[sql] returns ok Fri Aug 24 13:37:08 2012 : Info: ++? if (fail) Fri Aug 24 13:37:08 2012 : Info: ? Evaluating (fail) -> FALSE Fri Aug 24 13:37:08 2012 : Info: ++? if (fail) -> FALSE Sending Access-Reject of id 8 to 1.2.3.4 port 53575 Codigo-Reject = Cuenta-Bloqueada-Intentos-Reject EAP-Message = 0x04080004 Message-Authenticator = 0x00000000000000000000000000000000 LOG PEAP: Fri Aug 24 13:20:41 2012 : Debug: PEAP: Setting User-Name to prueba(a)test.es Sending tunneled request EAP-Message = 0x0208001501303237343736333240756e65782e6573 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "prueba(a)test.es" NAS-IP-Address = 2.2.2.2 NAS-Port-Type = Wireless-802.11 NAS-Port = 2 Framed-MTU = 1400 Calling-Station-Id = "C4:46:19:75:7B:B1" Called-Station-Id = "00-18-6E-D0-EC-04" NAS-Identifier = "Enterprise Wireless AP" server inner-tunnel { Fri Aug 24 13:20:41 2012 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-tunnel Fri Aug 24 13:20:41 2012 : Info: +- entering group authorize {...} Fri Aug 24 13:20:41 2012 : Info: expand: %u -> prueba(a)test.es Fri Aug 24 13:20:41 2012 : Info: ++[outer.request] returns notfound Fri Aug 24 13:20:41 2012 : Info: ++[mschap] returns noop Fri Aug 24 13:20:41 2012 : Info: [auth_log] expand: /var/log/freeradius/radacct/%Y/%m/%d/%{Client-IP-Address}-auth-detail-%Y%m%d -> /var/log/freeradius/radacct/2012/08/24/2.2.2.2-auth-detail-20120824 Fri Aug 24 13:20:41 2012 : Info: [auth_log] /var/log/freeradius/radacct/%Y/%m/%d/%{Client-IP-Address}-auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/2012/08/24/2.2.2.2-auth-detail-20120824 Fri Aug 24 13:20:41 2012 : Info: [auth_log] expand: %t -> Fri Aug 24 13:20:41 2012 Fri Aug 24 13:20:41 2012 : Info: ++[auth_log] returns ok Fri Aug 24 13:20:41 2012 : Info: [suffix] Looking up realm "test.es" for User-Name = "prueba(a)test.es" Fri Aug 24 13:20:41 2012 : Info: [suffix] Found realm "test.es" Fri Aug 24 13:20:41 2012 : Info: [suffix] Adding Stripped-User-Name = "prueba" Fri Aug 24 13:20:41 2012 : Info: [suffix] Adding Realm = "test.es" Fri Aug 24 13:20:41 2012 : Info: [suffix] Authentication realm is LOCAL. Fri Aug 24 13:20:41 2012 : Info: ++[suffix] returns ok Fri Aug 24 13:20:41 2012 : Info: ++[control] returns ok Fri Aug 24 13:20:41 2012 : Info: [eap] EAP packet type response id 8 length 21 Fri Aug 24 13:20:41 2012 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Fri Aug 24 13:20:41 2012 : Info: ++[eap] returns updated Fri Aug 24 13:20:41 2012 : Info: ++? if ("%{Realm}"=='test.es') Fri Aug 24 13:20:41 2012 : Info: expand: %{Realm} -> test.es Fri Aug 24 13:20:41 2012 : Info: ?? Evaluating ("%{Realm}"=='test.es') -> TRUE Fri Aug 24 13:20:41 2012 : Info: ++? if ("%{Realm}"=='test.es') -> TRUE Fri Aug 24 13:20:41 2012 : Info: ++- entering if ("%{Realm}"=='test.es') {...} Fri Aug 24 13:20:41 2012 : Info: sql_xlat Fri Aug 24 13:20:41 2012 : Info: expand: %{Stripped-User-Name} -> prueba Fri Aug 24 13:20:41 2012 : Info: expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> prueba Fri Aug 24 13:20:41 2012 : Info: sql_set_user escaped user --> 'prueba' Fri Aug 24 13:20:41 2012 : Info: expand: SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject' -> SELECT COUNT(*) from radpostauth WHERE username = 'prueba(a)test.es' AND authdate > CURRENT_DATE and reply = 'Access-Reject' Fri Aug 24 13:20:41 2012 : Debug: rlm_sql (sql): Reserving sql socket id: 3 Fri Aug 24 13:20:42 2012 : Info: sql_xlat finished Fri Aug 24 13:20:42 2012 : Debug: rlm_sql (sql): Released sql socket id: 3 Fri Aug 24 13:20:42 2012 : Info: expand: %{sql:SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject'} -> 7 Fri Aug 24 13:20:42 2012 : Info: sql_xlat Fri Aug 24 13:20:42 2012 : Info: expand: %{Stripped-User-Name} -> prueba Fri Aug 24 13:20:42 2012 : Info: expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> prueba Fri Aug 24 13:20:42 2012 : Info: sql_set_user escaped user --> 'prueba' Fri Aug 24 13:20:42 2012 : Info: expand: SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject' -> SELECT COUNT(*) from radpostauth WHERE username = 'prueba(a)test.es' AND authdate > CURRENT_DATE and reply = 'Access-Reject' Fri Aug 24 13:20:42 2012 : Debug: rlm_sql (sqlradiusba): Reserving sql socket id: 4 Fri Aug 24 13:20:42 2012 : Info: sql_xlat finished Fri Aug 24 13:20:42 2012 : Debug: rlm_sql (sqlradiusba): Released sql socket id: 4 Fri Aug 24 13:20:42 2012 : Info: expand: %{sqlradiusba:SELECT COUNT(*) from radpostauth WHERE username = '%{User-Name}' AND authdate > CURRENT_DATE and reply = 'Access-Reject'} -> 0 Fri Aug 24 13:20:42 2012 : Info: +++[request] returns updated Fri Aug 24 13:20:42 2012 : Info: ++- if ("%{Realm}"=='test.es') returns updated Fri Aug 24 13:20:42 2012 : Info: [files] users: Matched entry DEFAULT at line 29 Fri Aug 24 13:20:42 2012 : Info: [files] expand: %{Stripped-User-Name} -> prueba Fri Aug 24 13:20:42 2012 : Info: [files] expand: NUMERO DE INTENTOS FALLIDOS (%{Intentos-Reject}) EXCEDIDO PARA %{%{Stripped-User-Name}:-%{User-Name}} -> NUMERO DE INTENTOS FALLIDOS (7) EXCEDIDO PARA prueba Fri Aug 24 13:20:42 2012 : Info: [files] users: Matched entry DEFAULT at line 36 Fri Aug 24 13:20:42 2012 : Info: ++[files] returns ok Fri Aug 24 13:20:42 2012 : Info: ++? if ("%{control:Auth-Type}" == 'Reject') Fri Aug 24 13:20:42 2012 : Info: expand: %{control:Auth-Type} -> Reject Fri Aug 24 13:20:42 2012 : Info: ? Evaluating ("%{control:Auth-Type}" == 'Reject') -> TRUE Fri Aug 24 13:20:42 2012 : Info: ++? if ("%{control:Auth-Type}" == 'Reject') -> TRUE Fri Aug 24 13:20:42 2012 : Info: ++- entering if ("%{control:Auth-Type}" == 'Reject') {...} Fri Aug 24 13:20:42 2012 : Info: expand: %{reply:Codigo-Reject} -> Cuenta-Bloqueada-Intentos-Reject Fri Aug 24 13:20:42 2012 : Info: +++[outer.reply] returns ok Fri Aug 24 13:20:42 2012 : Info: +++[reject] returns reject Fri Aug 24 13:20:42 2012 : Info: ++- if ("%{control:Auth-Type}" == 'Reject') returns reject } # server inner-tunnel Fri Aug 24 13:20:42 2012 : Info: [peap] Got tunneled reply code 3 Reply-Message += "NUMERO DE INTENTOS FALLIDOS (7) EXCEDIDO PARA prueba" Codigo-Reject = Cuenta-Bloqueada-Intentos-Reject Fri Aug 24 13:20:42 2012 : Info: [peap] Got tunneled reply RADIUS code 3 Reply-Message += "NUMERO DE INTENTOS FALLIDOS (7) EXCEDIDO PARA prueba" Codigo-Reject = Cuenta-Bloqueada-Intentos-Reject Fri Aug 24 13:20:42 2012 : Info: [peap] Tunneled authentication was rejected. Fri Aug 24 13:20:42 2012 : Info: [peap] FAILURE Fri Aug 24 13:20:42 2012 : Info: ++[eap] returns handled Fri Aug 24 13:20:42 2012 : Info: } # server Sending Access-Challenge of id 32 to 2.2.2.2 port 1500 Codigo-Reject = Cuenta-Bloqueada-Intentos-Reject EAP-Message = 0x0109002b190017030100205f329253b5d9c4913c1f8f6f154f9d8771fa5a48be2993d753c9848b55710216 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xcbd9304bccd029a9cfcde266d7e75d03 Fri Aug 24 13:20:42 2012 : Info: Finished request 7. Fri Aug 24 13:20:42 2012 : Debug: Going to the next request Fri Aug 24 13:20:42 2012 : Debug: Waking up in 3.2 seconds. rad_recv: Access-Request packet from host 2.2.2.2 port 1501, id=33, length=205 NAS-IP-Address = 2.2.2.2 NAS-Port-Type = Wireless-802.11 NAS-Port = 2 Framed-MTU = 1400 User-Name = "prueba(a)test.es" Calling-Station-Id = "C4-46-19-75-7B-B1" Called-Station-Id = "00-18-6E-D0-EC-04" NAS-Identifier = "Enterprise Wireless AP" State = 0xcbd9304bccd029a9cfcde266d7e75d03 EAP-Message = 0x0209002b19001703010020d99c0d3ff24027b3d2f3d9ff6b999c50343b16224b5ea431c4f061165e9d7bbd Message-Authenticator = 0x9ea3d3262c5cf1762dfcc08226e0ff14 Fri Aug 24 13:20:42 2012 : Info: server { Fri Aug 24 13:20:42 2012 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/ Fri Aug 24 13:20:42 2012 : Info: +- entering group authorize {...} Fri Aug 24 13:20:42 2012 : Info: ++? if ("%{request:Calling-Station-Id}" =~ /^([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2})$/i ) Fri Aug 24 13:20:42 2012 : Info: expand: %{request:Calling-Station-Id} -> C4-46-19-75-7B-B1 Fri Aug 24 13:20:42 2012 : Info: ? Evaluating ("%{request:Calling-Station-Id}" =~ /^([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2})$/i) -> TRUE Fri Aug 24 13:20:42 2012 : Info: ++? if ("%{request:Calling-Station-Id}" =~ /^([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2})$/i ) -> TRUE Fri Aug 24 13:20:42 2012 : Info: ++- entering if ("%{request:Calling-Station-Id}" =~ /^([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2})$/i ) {...} Fri Aug 24 13:20:42 2012 : Info: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} -> C4:46:19:75:7B:B1 Fri Aug 24 13:20:42 2012 : Info: +++[request] returns notfound Fri Aug 24 13:20:42 2012 : Info: ++- if ("%{request:Calling-Station-Id}" =~ /^([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2}).?([0-9a-f]{2})$/i ) returns notfound Fri Aug 24 13:20:42 2012 : Info: [auth_log] expand: /var/log/freeradius/radacct/%Y/%m/%d/%{Client-IP-Address}-auth-detail-%Y%m%d -> /var/log/freeradius/radacct/2012/08/24/2.2.2.2-auth-detail-20120824 Fri Aug 24 13:20:42 2012 : Info: [auth_log] /var/log/freeradius/radacct/%Y/%m/%d/%{Client-IP-Address}-auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/2012/08/24/2.2.2.2-auth-detail-20120824 Fri Aug 24 13:20:42 2012 : Info: [auth_log] expand: %t -> Fri Aug 24 13:20:42 2012 Fri Aug 24 13:20:42 2012 : Info: ++[auth_log] returns ok Fri Aug 24 13:20:42 2012 : Info: [suffix] Looking up realm "test.es" for User-Name = "prueba(a)test.es" Fri Aug 24 13:20:42 2012 : Info: [suffix] Found realm "test.es" Fri Aug 24 13:20:42 2012 : Info: [suffix] Adding Stripped-User-Name = "prueba" Fri Aug 24 13:20:42 2012 : Info: [suffix] Adding Realm = "test.es" Fri Aug 24 13:20:42 2012 : Info: [suffix] Authentication realm is LOCAL. Fri Aug 24 13:20:42 2012 : Info: ++[suffix] returns ok Fri Aug 24 13:20:42 2012 : Info: [files] users: Matched entry DEFAULT at line 36 Fri Aug 24 13:20:42 2012 : Info: ++[files] returns ok Fri Aug 24 13:20:42 2012 : Info: [eap] EAP packet type response id 9 length 43 Fri Aug 24 13:20:42 2012 : Info: [eap] Continuing tunnel setup. Fri Aug 24 13:20:42 2012 : Info: ++[eap] returns ok Fri Aug 24 13:20:42 2012 : Info: Found Auth-Type = eap Fri Aug 24 13:20:42 2012 : Info: # Executing group from file /etc/freeradius/sites-enabled/ Fri Aug 24 13:20:42 2012 : Info: +- entering group authenticate {...} Fri Aug 24 13:20:42 2012 : Info: [eap] Request found, released from the list Fri Aug 24 13:20:42 2012 : Info: [eap] EAP/peap Fri Aug 24 13:20:42 2012 : Info: [eap] processing type peap Fri Aug 24 13:20:42 2012 : Info: [peap] processing EAP-TLS Fri Aug 24 13:20:42 2012 : Info: [peap] eaptls_verify returned 7 Fri Aug 24 13:20:42 2012 : Info: [peap] Done initial handshake Fri Aug 24 13:20:42 2012 : Info: [peap] eaptls_process returned 7 Fri Aug 24 13:20:42 2012 : Info: [peap] EAPTLS_OK Fri Aug 24 13:20:42 2012 : Info: [peap] Session established. Decoding tunneled attributes. Fri Aug 24 13:20:42 2012 : Info: [peap] Peap state send tlv failure Fri Aug 24 13:20:42 2012 : Info: [peap] Received EAP-TLV response. Fri Aug 24 13:20:42 2012 : Info: [peap] The users session was previously rejected: returning reject (again.) Fri Aug 24 13:20:42 2012 : Info: [peap] *** This means you need to read the PREVIOUS messages in the debug output Fri Aug 24 13:20:42 2012 : Info: [peap] *** to find out the reason why the user was rejected. Fri Aug 24 13:20:42 2012 : Info: [peap] *** Look for "reject" or "fail". Those earlier messages will tell you. Fri Aug 24 13:20:42 2012 : Info: [peap] *** what went wrong, and how to fix the problem. Fri Aug 24 13:20:42 2012 : Info: [eap] Handler failed in EAP/peap Fri Aug 24 13:20:42 2012 : Info: [eap] Failed in EAP select Fri Aug 24 13:20:42 2012 : Info: ++[eap] returns invalid Fri Aug 24 13:20:42 2012 : Info: Failed to authenticate the user. Fri Aug 24 13:20:42 2012 : Info: } # server Fri Aug 24 13:20:42 2012 : Info: Using Post-Auth-Type Reject Fri Aug 24 13:20:42 2012 : Info: # Executing group from file /etc/freeradius/sites-enabled/ Fri Aug 24 13:20:42 2012 : Info: +- entering group REJECT {...} Fri Aug 24 13:20:42 2012 : Info: ++[reply] returns noop Fri Aug 24 13:20:42 2012 : Info: [sql] expand: %{Stripped-User-Name} -> prueba Fri Aug 24 13:20:42 2012 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> prueba Fri Aug 24 13:20:42 2012 : Info: [sql] sql_set_user escaped user --> 'prueba' Fri Aug 24 13:20:42 2012 : Info: [sql] expand: INSERT INTO radpostauth (username, mac, client, reply, authdate,codreject,radauth) VALUES ( LOWER('%{User-Name}'), LOWER('%i'), '%C', '%{reply:Packet-Type}', NOW(), '%{reply:Codigo-Reject}','radiuscc') -> INSERT INTO radpostauth (username, mac, client, reply, authdate,codreject,radauth) VALUES ( LOWER('prueba(a)test.es'), LOWER('C4:46:19:75:7B:B1'), 'PACCIPV601I', 'Access-Reject', NOW(), 'Credenciales-Erroneas','radiuscc') Fri Aug 24 13:20:42 2012 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, mac, client, reply, authdate,codreject,radauth) VALUES ( LOWER('prueba(a)test.es'), LOWER('C4:46:19:75:7B:B1'), 'PACCIPV601I', 'Access-Reject', NOW(), 'Credenciales-Erroneas','radiuscc') Fri Aug 24 13:20:42 2012 : Debug: rlm_sql (sql): Reserving sql socket id: 2 Fri Aug 24 13:20:42 2012 : Debug: rlm_sql (sql): Released sql socket id: 2 Fri Aug 24 13:20:42 2012 : Info: ++[sql] returns ok Fri Aug 24 13:20:42 2012 : Info: ++? if (fail) Fri Aug 24 13:20:42 2012 : Info: ? Evaluating (fail) -> FALSE Fri Aug 24 13:20:42 2012 : Info: ++? if (fail) -> FALSE Fri Aug 24 13:20:42 2012 : Info: Delaying reject of request 8 for 1 seconds Fri Aug 24 13:20:42 2012 : Debug: Going to the next request Fri Aug 24 13:20:42 2012 : Debug: Waking up in 0.9 seconds. Fri Aug 24 13:20:43 2012 : Info: Sending delayed reject for request 8 Sending Access-Reject of id 33 to 2.2.2.2 port 1501 EAP-Message = 0x04090004 Message-Authenticator = 0x00000000000000000000000000000000 Codigo-Reject = Credenciales-Erroneas Any ideas about how can I do that? Thank you very much and sorry for my english Ana Gallardo

4 6