PEAP failure problem
UEX Ana Gallardo Gómez
aigallardo at unex.es
Thu Sep 6 11:28:28 CEST 2012
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 at 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 at 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 at 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 at 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 at 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 at 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 at test.es
Fri Aug 24 13:37:08 2012 : Info: [sql] expand: %{%{User-Name}:-DEFAULT}
-> prueba at test.es
Fri Aug 24 13:37:08 2012 : Info: [sql] expand:
%{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> prueba at test.es
Fri Aug 24 13:37:08 2012 : Info: [sql] sql_set_user escaped user --> '
prueba at 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 at 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 at 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 at test.es
Sending tunneled request
EAP-Message = 0x0208001501303237343736333240756e65782e6573
FreeRADIUS-Proxied-To = 127.0.0.1
User-Name = "prueba at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120906/66ff7c79/attachment-0001.html>
More information about the Freeradius-Users
mailing list