freeradius PEAP/MS-CHAPv2 and aegis client

Hi, All,
I am setting up a freeradius server to do PEAP authentication with
MS-CHAPv2. My freeradius version is 1.0.1. The supplicant is a PC
running aegis client version 2.0.5.
The authenticator is a Cisco Switch with dot1x enabled.
When trying to authenticate the client, I always received the
following debugging messages with the authentication failure:


...........
for request 6
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: EAP packet type response id 6 lengt
h 107
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: No EAP Start, assuming it's an on-g
oing EAP conversation
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from eap (rlm
_eap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "eap" returns upd
ated for request 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling files (rlm_fil
es) for request 6
Tue Apr 12 15:21:36 2005 : Debug: users: Matched supplicant_cts at 55
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from files (r
lm_files) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "files" returns o
k for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall: group authorize returns updated for r
equest 6
Tue Apr 12 15:21:36 2005 : Debug: rad_check_password: Found Auth-Type EAP
Tue Apr 12 15:21:36 2005 : Debug: auth: type "EAP"
Tue Apr 12 15:21:36 2005 : Debug: Processing the authenticate section of radiu
sd.conf
Tue Apr 12 15:21:36 2005 : Debug: modcall: entering group authenticate for reque
st 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: calling eap (rlm_ea
p) for request 6
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: Request found, released from the li
st
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: EAP/peap
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: processing type peap
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: Authenticate
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_tls: processing TLS
Tue Apr 12 15:21:36 2005 : Debug: eaptls_verify returned 7
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_tls: Done initial handshake
Tue Apr 12 15:21:36 2005 : Debug: eaptls_process returned 7
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: EAPTLS_OK
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: Session established. Decoding
tunneled attributes.
PEAP tunnel data in 0000: 1a 02 06 00 44 31 9f 11 f4 59 4e c9 74 2b dd 1b
PEAP tunnel data in 0010: a2 c0 bf 28 fa ea 00 00 00 00 00 00 00 00 c8 3c
PEAP tunnel data in 0020: 75 64 f3 38 a5 42 35 96 e8 c2 84 5a 74 0e ec 42
PEAP tunnel data in 0030: d9 2e 69 41 4e a3 00 73 75 70 70 6c 69 63 61 6e
PEAP tunnel data in 0040: 74 5f 63 74 73
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: EAP type mschapv2
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: Tunneled data is valid.
PEAP: Got tunneled EAP-Message
EAP-Message = 0x020600491a02060044319f11f4594ec9742bdd1ba2c0bf28 faea0000
000000000000c83c7564f338a5423596e8c2845a740eec42d9 2e69414ea300737570706c6963616e
745f637473
Tue Apr 12 15:21:36 2005 : Debug: PEAP: Setting User-Name to supplicant_cts
Tue Apr 12 15:21:36 2005 : Debug: PEAP: Adding old state with 9c 22
PEAP: Sending tunneled request
EAP-Message = 0x020600491a02060044319f11f4594ec9742bdd1ba2c0bf28 faea0000
000000000000c83c7564f338a5423596e8c2845a740eec42d9 2e69414ea300737570706c6963616e
745f637473
FreeRADIUS-Proxied-To = 127.0.0.1
User-Name = "supplicant_cts"
State = 0x9c22748acfa58b214fe3d20fac288a7a
Tue Apr 12 15:21:36 2005 : Debug: Processing the authorize section of radiusd.
conf
Tue Apr 12 15:21:36 2005 : Debug: modcall: entering group authorize for request
6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling preprocess (rl
m_preprocess) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from preproce
ss (rlm_preprocess) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "preprocess" retu
rns ok for request 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling chap (rlm_chap
) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from chap (rl
m_chap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "chap" returns no
op for request 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling mschap (rlm_ms
chap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from mschap (
rlm_mschap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "mschap" returns
noop for request 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling suffix (rlm_re
alm) for request 6
Tue Apr 12 15:21:36 2005 : Debug: rlm_realm: No '@' in User-Name = "supplica
nt_cts", looking up realm NULL
Tue Apr 12 15:21:36 2005 : Debug: rlm_realm: No such realm "NULL"
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from suffix (
rlm_realm) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "suffix" returns
noop for request 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling eap (rlm_eap)
for request 6
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: EAP packet type response id 6 lengt
h 73
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: No EAP Start, assuming it's an on-g
oing EAP conversation
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from eap (rlm
_eap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "eap" returns upd
ated for request 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling files (rlm_fil
es) for request 6
Tue Apr 12 15:21:36 2005 : Debug: users: Matched supplicant_cts at 55
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from files (r
lm_files) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "files" returns o
k for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall: group authorize returns updated for r
equest 6
Tue Apr 12 15:21:36 2005 : Debug: rad_check_password: Found Auth-Type EAP
Tue Apr 12 15:21:36 2005 : Debug: auth: type "EAP"
Tue Apr 12 15:21:36 2005 : Debug: Processing the authenticate section of radiu
sd.conf
Tue Apr 12 15:21:36 2005 : Debug: modcall: entering group authenticate for reque
st 6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: calling eap (rlm_ea
p) for request 6
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: Request found, released from the li
st
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: EAP/mschapv2
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: processing type mschapv2
Tue Apr 12 15:21:36 2005 : Debug: Processing the authenticate section of radiu
sd.conf
Tue Apr 12 15:21:36 2005 : Debug: modcall: entering group Auth-Type for request
6
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: calling mschap (rlm
_mschap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: rlm_mschap: Told to do MS-CHAPv2 for supplic
ant_cts with NT-Password
Tue Apr 12 15:21:36 2005 : Debug: rlm_mschap: FAILED: MS-CHAP2-Response is inc
orrect
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: returned from mscha
p (rlm_mschap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authenticate]: module "mschap" retur
ns reject for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall: group Auth-Type returns reject for re
quest 6
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: Freeing handler
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: returned from eap (
rlm_eap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authenticate]: module "eap" returns
reject for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall: group authenticate returns reject for
request 6
Tue Apr 12 15:21:36 2005 : Debug: auth: Failed to validate the user.
PEAP: Got tunneled reply RADIUS code 3
MS-CHAP-Error = "\006E=691 R=1"
EAP-Message = 0x04060004
Message-Authenticator = 0x00000000000000000000000000000000
PEAP: Processing from tunneled session code 1bcf10 3
MS-CHAP-Error = "\006E=691 R=1"
EAP-Message = 0x04060004
Message-Authenticator = 0x00000000000000000000000000000000
Tue Apr 12 15:21:36 2005 : Debug: PEAP: Tunneled authentication was rejected.
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: FAILURE
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: returned from eap (
rlm_eap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall[authenticate]: module "eap" returns
handled for request 6
Tue Apr 12 15:21:36 2005 : Debug: modcall: group authenticate returns handled fo
r request 6
Sending Access-Challenge of id 5 to 10.15.126.50:1812
EAP-Message = 0x010700481900170301001885fcc9fc72bad597097b417985 350c0bba
7d0b3c11b4ccea17030100206c13e33e0ef99b7bde49938323 f5c743560fc13b2b9d5c32f8a477d0
004c3bbf
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xe0770faeb9f689d74c1bf292a25184a9
Tue Apr 12 15:21:36 2005 : Debug: Finished request 6
Tue Apr 12 15:21:36 2005 : Debug: Going to the next request
Tue Apr 12 15:21:36 2005 : Debug: Thread 2 waiting to be assigned a request
rad_recv: Access-Request packet from host 10.15.126.50:1812, id=6, length=185
Tue Apr 12 15:21:36 2005 : Debug: Waking up in 6 seconds...
Tue Apr 12 15:21:36 2005 : Debug: Thread 3 got semaphore
Tue Apr 12 15:21:36 2005 : Debug: Thread 3 handling request 7, (2 handled so far
)
NAS-IP-Address = 10.15.126.50
NAS-Port = 50010
NAS-Port-Type = Ethernet
User-Name = "supplicant_cts"
Called-Station-Id = "00-0A-41-54-AE-8A"
Calling-Station-Id = "00-50-04-B2-07-A3"
Service-Type = Framed-User
Framed-MTU = 1500
State = 0xe0770faeb9f689d74c1bf292a25184a9
EAP-Message = 0x0207002b19001703010020ef1d835462f8c18ee37c07d87c f707644f
b833c5e5fb483f7657141f308b2fd0
Message-Authenticator = 0x242951d9af3eb1dbfc287fe6d89f4408
Tue Apr 12 15:21:36 2005 : Debug: Processing the authorize section of radiusd.
conf
Tue Apr 12 15:21:36 2005 : Debug: modcall: entering group authorize for request
7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling preprocess (rl
m_preprocess) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from preproce
ss (rlm_preprocess) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "preprocess" retu
rns ok for request 7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling chap (rlm_chap
) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from chap (rl
m_chap) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "chap" returns no
op for request 7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling mschap (rlm_ms
chap) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from mschap (
rlm_mschap) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "mschap" returns
noop for request 7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling suffix (rlm_re
alm) for request 7
Tue Apr 12 15:21:36 2005 : Debug: rlm_realm: No '@' in User-Name = "supplica
nt_cts", looking up realm NULL
Tue Apr 12 15:21:36 2005 : Debug: rlm_realm: No such realm "NULL"
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from suffix (
rlm_realm) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "suffix" returns
noop for request 7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling eap (rlm_eap)
for request 7
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: EAP packet type response id 7 lengt
h 43
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: No EAP Start, assuming it's an on-g
oing EAP conversation
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from eap (rlm
_eap) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "eap" returns upd
ated for request 7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: calling files (rlm_fil
es) for request 7
Tue Apr 12 15:21:36 2005 : Debug: users: Matched supplicant_cts at 55
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authorize]: returned from files (r
lm_files) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modcall[authorize]: module "files" returns o
k for request 7
Tue Apr 12 15:21:36 2005 : Debug: modcall: group authorize returns updated for r
equest 7
Tue Apr 12 15:21:36 2005 : Debug: rad_check_password: Found Auth-Type EAP
Tue Apr 12 15:21:36 2005 : Debug: auth: type "EAP"
Tue Apr 12 15:21:36 2005 : Debug: Processing the authenticate section of radiu
sd.conf
Tue Apr 12 15:21:36 2005 : Debug: modcall: entering group authenticate for reque
st 7
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: calling eap (rlm_ea
p) for request 7
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: Request found, released from the li
st
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: EAP/peap
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: processing type peap
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: Authenticate
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_tls: processing TLS
Tue Apr 12 15:21:36 2005 : Debug: eaptls_verify returned 7
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_tls: Done initial handshake
Tue Apr 12 15:21:36 2005 : Debug: eaptls_process returned 7
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: EAPTLS_OK
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: Session established. Decoding
tunneled attributes.
PEAP tunnel data in 0000: 02 07 00 0b 21 80 03 00 02 00 02
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: Received EAP-TLV response.
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: Tunneled data is valid.
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap_peap: Had sent TLV failure, rejecti
ng.
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: Handler failed in EAP/peap
Tue Apr 12 15:21:36 2005 : Debug: rlm_eap: Failed in EAP select
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: returned from eap (
rlm_eap) for request 7
Tue Apr 12 15:21:36 2005 : Debug: modcall[authenticate]: module "eap" returns
invalid for request 7
Tue Apr 12 15:21:36 2005 : Debug: modcall: group authenticate returns invalid fo
r request 7
Tue Apr 12 15:21:36 2005 : Debug: auth: Failed to validate the user.
Tue Apr 12 15:21:36 2005 : Debug: Delaying request 7 for 1 seconds
Tue Apr 12 15:21:36 2005 : Debug: Finished request 7
Tue Apr 12 15:21:36 2005 : Debug: Going to the next request
Tue Apr 12 15:21:36 2005 : Debug: Thread 3 waiting to be assigned a request
rad_recv: Access-Request packet from host 10.15.126.50:1812, id=6, length=185
Sending Access-Reject of id 6 to 10.15.126.50:1812
EAP-Message = 0x04070004
Message-Authenticator = 0x00000000000000000000000000000000
......

my radiusd.conf is like this:

......

modules {
$INCLUDE ${confdir}/eap.conf

mschap {
authtype = MS-CHAP
}
}
.....

my eap.conf is:

eap {
default_eap_type = peap
timer_expire = 60

ignore_unknown_eap_types = no

cisco_accounting_username_bug = no

# Supported EAP-types

#
# We do NOT recommend using EAP-MD5 authentication
# for wireless connections. It is insecure, and does
# not provide for dynamic WEP keys.
#
md5 {
}

tls {
private_key_password = whatever
private_key_file = ${raddbdir}/certs/cert-srv.pem

certificate_file = ${raddbdir}/certs/cert-srv.pem

CA_file = ${raddbdir}/certs/demoCA/cacert.pem

dh_file = ${raddbdir}/certs/dh
random_file = ${raddbdir}/certs/random

fragment_size = 1024

include_length = yes
check_cert_cn = %{User-Name}
}

peap {
default_eap_type = mschapv2
}
mschapv2 {
}
}

my users file is like this:

"supplicant_cts@spirentcom.com" Auth-Type := EAP, User-Password == "secret"
"supplicant_cts1@spirentcom.com" Auth-Type := EAP, User-Password == "secret1"
"supplicant_cts" Auth-Type := EAP, User-Password == "whatever"
"supplicant_cts" User-Password == "whatever"

Can you please try to find out what caused the authentication failure,
specifically the following error? what configuration did I miss for
the radius server?
.....

Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: calling mschap (rlm
_mschap) for request 6
Tue Apr 12 15:21:36 2005 : Debug: rlm_mschap: Told to do MS-CHAPv2 for supplic
ant_cts with NT-Password
Tue Apr 12 15:21:36 2005 : Debug: rlm_mschap: FAILED: MS-CHAP2-Response is inc
orrect
Tue Apr 12 15:21:36 2005 : Debug: modsingle[authenticate]: returned from mscha
p (rlm_mschap) for request 6
.....

Thank you very much.

Jie

-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html