Hi,I am trying to set up Freeradius to proxy PEAP/EAP-MSCHAPv2 request as MSCHAPv2 and know that some of you were able to set up this cofiguration successfully i.e.
http://www.mail-archive.com/freeradius-users@lists.freeradius.org/msg22903.html http://www.mail-archive.com/freeradius-users@lists.freeradius.org/msg16192.html and others.
I have tried the examples in those postings as well as suggestions from other
postings without any success. I have started with the default config and turned
on the debug option. However, looking at the debug output yet I couldn't quite
figure out what went wrong.
What I got so far is as follow:
1) Send a PEAP/MSCHAPv2 request using Linux's Xsupplicant or Mac client to the
proxy radius
2) Proxy radius terminated EAP locally and proxied request (MSCHAPv2 minus EAP)
to home radius
3) Home radius responded with an access-accept packet to proxy radius
4) Proxy Radius sent access-reject to client. See error output below.
Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: Request not found in the list
Tue Oct 3 20:10:37 2006 : Error: rlm_eap: Either EAP-request timed out OR
EAP-response
to an unknown EAP-request
Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: Failed in handler
I am running Freeradius 1.1.3 and have attached below my configuration files
and an excerpt of
the debug output hoping that the mistake would look obvious to some of you and
that you could
provide some helpful pointers or links.
Thanks a lot for your help.
-David
For the outer identity, I have set it to use 'Anonymous' and the inner identity,
I have set it to use '[EMAIL PROTECTED]'
radiusd.conf
modules {
pap {
encryption_scheme = crypt
}
chap {
authtype = CHAP
}
pam {
pam_auth = radiusd
}
$INCLUDE ${confdir}/eap.conf
mschap {
authtype = MS-CHAP
use_mppe = yes
require_encryption = yes
require_strong = yes
}
realm IPASS {
format = prefix
delimiter = "/"
ignore_default = no
ignore_null = no
}
# '[EMAIL PROTECTED]'
#
realm suffix {
format = suffix
delimiter = "@"
ignore_default = no
ignore_null = no
}
...
}
authorize {
preprocess
chap
mschap
suffix
eap
files
}
authenticate {
Auth-Type PAP {
pap
}
Auth-Type CHAP {
chap
}
Auth-Type MS-CHAP {
mschap
}
eap
}
preacct {
preprocess
acct_unique
suffix
files
}
accounting {
detail
radutmp
}
session {
radutmp
}
post-auth {
}
pre-proxy {
}
post-proxy {
eap
}
eap.conf
eap {
default_eap_type = peap
timer_expire = 60
ignore_unknown_eap_types = no
cisco_accounting_username_bug = no
md5 {
}
leap {
}
gtc {
auth_type = PAP
}
tls {
private_key_password = wireless
private_key_file = ${raddbdir}/certs/host.key
certificate_file = ${raddbdir}/certs/host.crt
CA_file = ${raddbdir}/certs/ca-root.crt
dh_file = ${raddbdir}/certs/dh
random_file = /dev/urandom
}
ttls {
default_eap_type = md5
copy_request_to_tunnel = yes
use_tunneled_reply = yes
}
peap {
default_eap_type = mschapv2
copy_request_to_tunnel = yes
use_tunneled_reply = yes
proxy_tunneled_request_as_eap = no
# Note: If I set proxy_tunneled_request_as_eap = yes (proxying
the request as eap-mschapv2)
# I was able to connect successfully
}
mschapv2 {
}
}
proxy.conf
realm LOCAL {
type = radius
authhost = LOCAL
accthost = LOCAL
}
realm NULL {
type = radius
authhost = LOCAL
accthost = LOCAL
}
realm abc.net {
type = radius
authhost = 199.186.1.2:1645
accthost = 199.186.1.2:1646
secret = wireless
nostrip
}
users:
DEFAULT FreeRADIUS-Proxied-To == 127.0.0.1, Proxy-To-Realm := "abc.net"
Debug output (excerpt starting when the home radius replied with an access
accept)
see attached files for the complete output.
Tue Oct 3 20:10:37 2006 : Sending Access-Request of id 30 to 199.186.1.2 port
1645
User-Name = "[EMAIL PROTECTED]"
NAS-IP-Address = 192.168.2.3
NAS-Identifier = "SJC=s=-=s=QE"
NAS-Port-Type = "Wireless - IEEE 802.11"
NAS-Port = 472
Called-Station-Id = "00-0D-97-00-48-01:AAA"
Calling-Station-Id = "00-16-CB-B9-D7-41"
Acct-Session-Id = "2LkFMyhUNqa+"
Connect-Info = "CONNECT 11Mbps 802.11b"
Service-Type = Framed-User
MS-CHAP-Challenge = 0x69e38b9d3be5408dc1740b695350adc6
MS-CHAP2-Response =
0x066ff5f8d276b161dc41b283b74961fde2760000000000000000ee7baf48902aedad5b6c47209b1d2794992879f402
d3eac4
Proxy-State = 0x313534
Tue Oct 3 20:10:37 2006 : Debug: Waking up in 2 seconds...
Tue Oct 3 20:10:37 2006 : rad_recv: Access-Accept packet from host
199.186.1.2:1645,
id=30, length=184
Tue Oct 3 20:10:37 2006 : Debug: proxy: de-allocating c6b903f6:1645 30
MS-CHAP2-Success =
0x06533d46313445394339363839414443393932343130324542383245334434423741443046384231313436
MS-MPPE-Recv-Key = 0xb6de1db8e81dfea9e7d51b6120a6a2e0
MS-MPPE-Send-Key = 0xa2db97000b60f3715d2068a05f0eb1dd
MS-MPPE-Encryption-Policy = 0x00000002
MS-MPPE-Encryption-Types = 0x00000006
Proxy-State = 0x313534
Tue Oct 3 20:10:37 2006 : Debug: Processing the post-proxy section of
radiusd.conf
Tue Oct 3 20:10:37 2006 : Debug: modcall: entering group post-proxy for request
250
Tue Oct 3 20:10:37 2006 : Debug: modsingle[post-proxy]: calling eap (rlm_eap)
for request 250 (0)
Tue Oct 3 20:10:37 2006 : Debug: PEAP: Passing reply from proxy back into the
tunnel.
Tue Oct 3 20:10:37 2006 : Debug: PEAP: Passing reply back for EAP-MS-CHAP-V2
16c490 2
Tue Oct 3 20:10:37 2006 : Debug: Processing the post-proxy section of radiusd.conf Tue Oct 3 20:10:37 2006 : Debug: modcall: entering group post-proxy for request 250 Tue Oct 3 20:10:37 2006 : Debug: modsingle[post-proxy]: calling eap (rlm_eap) for request 250 (2) Tue Oct 3 20:10:37 2006 : Debug: rlm_eap_mschapv2: Passing reply from proxy back into the tunnel 16c490 2. Tue Oct 3 20:10:37 2006 : Debug: rlm_eap_mschapv2: Authentication succeeded. Tue Oct 3 20:10:37 2006 : Debug: MSCHAP SuccessTue Oct 3 20:10:37 2006 : Debug: modsingle[post-proxy]: ok returned from eap (rlm_eap) for request 250 Tue Oct 3 20:10:37 2006 : Debug: modcall[post-proxy]: module "eap" returns ok for request 250
Tue Oct 3 20:10:37 2006 : Debug: modcall: leaving group post-proxy (returns ok) for request 250 Tue Oct 3 20:10:37 2006 : Debug: POST-PROXY 2 Tue Oct 3 20:10:37 2006 : Debug: POST-AUTH 2 Tue Oct 3 20:10:37 2006 : Debug: PEAP: Got reply 11 Tue Oct 3 20:10:37 2006 : Debug: PEAP: Got tunneled Access-Challenge Tue Oct 3 20:10:37 2006 : Debug: Saving tunneled attributes for later Tue Oct 3 20:10:37 2006 : Debug: PEAP: Reply was handledTue Oct 3 20:10:37 2006 : Debug: modsingle[post-proxy]: ok returned from eap (rlm_eap) for request 250 Tue Oct 3 20:10:37 2006 : Debug: modcall[post-proxy]: module "eap" returns ok for request 250
Tue Oct 3 20:10:37 2006 : Debug: modcall: leaving group post-proxy (returns ok)
for request 250
Tue Oct 3 20:10:37 2006 : Sending Access-Challenge of id 154 to 192.168.2.3
port
11061
EAP-Message =
0x0107004e19001703010043a102f2b10f2cc23294968cce980785e16f478376f3363f7e260a4151a06470265144600e5157f3
3a11db17f9532985d72bc321a6b264092151734087a050065f761093
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x29916516b9091aa773a614b242bf1cbb
Tue Oct 3 20:10:37 2006 : Debug: Finished request 250
Tue Oct 3 20:10:37 2006 : Debug: Going to the next request
Tue Oct 3 20:10:37 2006 : Debug: Waking up in 2 seconds...
Tue Oct 3 20:10:37 2006 : rad_recv: Access-Request packet from host
192.168.2.3:11061,
id=155, length=230
NAS-IP-Address = 192.168.2.3
NAS-Identifier = "SJC=s=-=s=QE"
NAS-Port-Type = "Wireless - IEEE 802.11"
NAS-Port = 472
Called-Station-Id = "00-0D-97-00-48-01:AAA"
Calling-Station-Id = "00-16-CB-B9-D7-41"
Acct-Session-Id = "2LkFMyhUNqa+"
Connect-Info = "CONNECT 11Mbps 802.11b"
User-Name = "anonymous"
State = 0x29916516b9091aa773a614b242bf1cbb
Service-Type = Framed-User
EAP-Message =
0x02070021190017030100168d386231a769e270b8e6a25148612d4e941daab20a5e
Message-Authenticator = 0x99c11169be9162c0de5982800e2a0b64
Tue Oct 3 20:10:37 2006 : Debug: Processing the authorize section of
radiusd.conf
Tue Oct 3 20:10:37 2006 : Debug: modcall: entering group authorize for request
251
Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: ok returned from preprocess (rlm_preprocess) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "preprocess" returns ok for request 251 Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: noop returned from chap (rlm_chap) for request 251Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "chap" returns noop for request 251
Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: noop returned from mschap (rlm_mschap) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "mschap" returns noop for request 251 Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: No '@' in User-Name = "anonymous", looking up realm NULL Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Found realm "NULL" Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Adding Stripped-User-Name = "anonymous" Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Proxying request from user anonymous to realm NULL Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Adding Realm = "NULL" Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Authentication realm is LOCAL. Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: noop returned from suffix (rlm_realm) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "suffix" returns noop for request 251Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 251 (0)
Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: EAP packet type response id 7 length 33Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: No EAP Start, assuming it's an on-going EAP conversation Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: updated returned from eap (rlm_eap) for request 251
Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "eap" returns updated for request 251 Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling files (rlm_files) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: users: 'anonymous' matched entry "DEFAULT" at line 129 Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: ok returned from files (rlm_files) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "files" returns ok for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall: leaving group authorize (returns updated) for request 251 Tue Oct 3 20:10:37 2006 : Debug: rad_check_password: Found Auth-Type EAP Tue Oct 3 20:10:37 2006 : Debug: auth: type "EAP" Tue Oct 3 20:10:37 2006 : Debug: Processing the authenticate section of radiusd.conf Tue Oct 3 20:10:37 2006 : Debug: modcall: entering group authenticate for request 251 Tue Oct 3 20:10:37 2006 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: Request found, released from the list Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: EAP/peap Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: processing type peap Tue Oct 3 20:10:37 2006 : Debug: rlm_eap_peap: Authenticate Tue Oct 3 20:10:37 2006 : Debug: rlm_eap_tls: processing TLS Tue Oct 3 20:10:37 2006 : Debug: eaptls_verify returned 7 Tue Oct 3 20:10:37 2006 : Debug: rlm_eap_tls: Done initial handshake Tue Oct 3 20:10:37 2006 : Debug: eaptls_process returned 7 Tue Oct 3 20:10:37 2006 : Debug: rlm_eap_peap: EAPTLS_OK Tue Oct 3 20:10:37 2006 : Debug: rlm_eap_peap: Session established. Decoding tunneled attributes. Tue Oct 3 20:10:37 2006 : Debug: rlm_eap_peap: EAP type mschapv2 Tue Oct 3 20:10:37 2006 : Debug: rlm_eap_peap: Tunneled data is valid. Tue Oct 3 20:10:37 2006 : Debug: PEAP: Setting User-Name to [EMAIL PROTECTED] Tue Oct 3 20:10:37 2006 : Debug: PEAP: Adding old state with bc 97 Tue Oct 3 20:10:37 2006 : Debug: Processing the authorize section of radiusd.confTue Oct 3 20:10:37 2006 : Debug: modcall: entering group authorize for request 251
Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: ok returned from preprocess (rlm_preprocess) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "preprocess" returns ok for request 251 Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: noop returned from chap (rlm_chap) for request 251Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "chap" returns noop for request 251
Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: noop returned from mschap (rlm_mschap) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "mschap" returns noop for request 251 Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Looking up realm "abc.net" for User-Name = "[EMAIL PROTECTED]" Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Found realm "abc.net" Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Proxying request from user peapuser to realm abc.net Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Adding Realm = "abc.net" Tue Oct 3 20:10:37 2006 : Debug: rlm_realm: Preparing to proxy authentication request to realm "abc.net"Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: updated returned from suffix (rlm_realm) for request 251
Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "suffix" returns updated for request 251Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 251 (0)
Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: Request is supposed to be proxied to Realm abc.net. Not doing EAP. Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: noop returned from eap (rlm_eap) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "eap" returns noop for request 251 Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: calling files (rlm_files) for request 251 (0)Tue Oct 3 20:10:37 2006 : Debug: users: '[EMAIL PROTECTED]' matched entry "DEFAULT" at line 129
Tue Oct 3 20:10:37 2006 : Debug: modsingle[authorize]: ok returned from files (rlm_files) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authorize]: module "files" returns ok for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall: leaving group authorize (returns updated) for request 251 Tue Oct 3 20:10:37 2006 : Debug: PEAP: Calling authenticate in order to initiate t/unneled EAP session. Tue Oct 3 20:10:37 2006 : Debug: Processing the authenticate section of radiusd.conf Tue Oct 3 20:10:37 2006 : Debug: modcall: entering group authenticate for request 251 Tue Oct 3 20:10:37 2006 : Debug: modsingle[authenticate]: calling eap (rlm_eap) for request 251 (0) Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: Request not found in the list Tue Oct 3 20:10:37 2006 : Error: rlm_eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: Failed in handler Tue Oct 3 20:10:37 2006 : Debug: modsingle[authenticate]: invalid returned from eap (rlm_eap) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authenticate]: module "eap" returns invalid for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall: leaving group authenticate (returns invalid) for request 251 Tue Oct 3 20:10:37 2006 : Debug: PEAP: Can't handle the return code 4 Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: Handler failed in EAP/peap Tue Oct 3 20:10:37 2006 : Debug: rlm_eap: Failed in EAP select Tue Oct 3 20:10:37 2006 : Debug: modsingle[authenticate]: invalid returned from eap (rlm_eap) for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall[authenticate]: module "eap" returns invalid for request 251 Tue Oct 3 20:10:37 2006 : Debug: modcall: leaving group authenticate (returns invalid) for request 251 Tue Oct 3 20:10:37 2006 : Debug: auth: Failed to validate the user. Tue Oct 3 20:10:37 2006 : Debug: Delaying request 251 for 1 seconds Tue Oct 3 20:10:37 2006 : Debug: Finished request 251 Tue Oct 3 20:10:37 2006 : Debug: Going to the next request Tue Oct 3 20:10:37 2006 : Debug: Waking up in 2 seconds... Tue Oct 3 20:10:39 2006 : Debug: --- Walking the entire request list ---Tue Oct 3 20:10:39 2006 : Debug: Cleaning up request 244 ID 148 with timestamp 4522fbf9 Tue Oct 3 20:10:39 2006 : Debug: Cleaning up request 245 ID 149 with timestamp 4522fbf9 Tue Oct 3 20:10:39 2006 : Debug: Cleaning up request 246 ID 150 with timestamp 4522fbf9 Tue Oct 3 20:10:39 2006 : Debug: Cleaning up request 247 ID 151 with timestamp 4522fbf9
Tue Oct 3 20:10:39 2006 : Sending Access-Reject of id 155 to 192.168.2.3 port
11061
EAP-Message = 0x04070004
Message-Authenticator = 0x00000000000000000000000000000000
Tue Oct 3 20:10:39 2006 : Debug: Waking up in 4 seconds...
Tue Oct 3 20:10:43 2006 : Debug: --- Walking the entire request list ---
Tue Oct 3 20:10:43 2006 : Debug: Cleaning up request 248 ID 152 with timestamp
4522fbfd
Tue Oct 3 20:10:43 2006 : Debug: Cleaning up request 249 ID 153 with timestamp
4522fbfd
Tue Oct 3 20:10:43 2006 : Debug: Cleaning up request 250 ID 154 with timestamp
4522fbfd
Tue Oct 3 20:10:43 2006 : Debug: Cleaning up request 251 ID 155 with timestamp
4522fbfd
Tue Oct 3 20:10:43 2006 : Debug: Nothing to do. Sleeping until we see a request.
debug.txt.gz
Description: application/gzip
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
