PEAP failure problem

27 Aug 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@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@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@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@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@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@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@test.es
Fri Aug 24 13:37:08 2012 : Info: [sql]     expand: %{%{User-Name}:-DEFAULT}
-> prueba@test.es
Fri Aug 24 13:37:08 2012 : Info: [sql]     expand:
%{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> prueba@test.es
Fri Aug 24 13:37:08 2012 : Info: [sql] sql_set_user escaped user --> '
prueba@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@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@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@test.es
Sending tunneled request
    EAP-Message = 0x0208001501303237343736333240756e65782e6573
    FreeRADIUS-Proxied-To = 127.0.0.1
    User-Name = "prueba@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@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@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@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@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@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@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@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@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

PEAP failure problem

Ana Gallardo Gómez