Proxy PEAP-EAP-MSCHAPv2 as MSCHAPv2

david chew davidchew at earthlink.net
Fri Oct 6 09:25:55 CEST 2006


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 'peapuser at abc.net'

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
        }

        #  'username at realm'
        #
        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 = "peapuser at abc.net"
        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 Success
Tue 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 handled
Tue 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 251
Tue 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 251
Tue 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
33
Tue 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 peapuser at abc.net
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.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 251
Tue 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 = "peapuser at abc.net"
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 251
Tue 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: 'peapuser at abc.net' 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.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: debug.txt.gz
Type: application/gzip
Size: 7277 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20061006/87715877/attachment.bin>


More information about the Freeradius-Users mailing list