Umm... dumb question, but you don't have "eap" listed in the
authenticate section of your radiusd.conf file twice do you?
--Mike
On Wed, 2003-11-19 at 12:31, Bill Reid wrote:
> Hey everyone,
>
> I continue to have a problem using peap with
> freeradius-snapshot-20031110. From what I have read about EAP, and
> from my discussions with others on this list, I believe I am seeing a
> problem from freeradius.
>
> Please correct me if I am wrong.
>
> According to the documentation in ./doc/rlm_eap. The client is not
> responding to step 6 "Access Challenge" from the radius server. I can
> see the Radius packet making it to the client. The only thing I can
> find that is odd about the challenge is that there are two eap portions
> of the frame. My hope is that the client is ignoring the frame because
> of this.
>
> Since there is no response from the client(supplicant) I do not get an
> EAP-Success/EAP-failure and begin to negotiate any ssl/wep stuff. So I
> don't even think I am verifying the server using the installed CERT at
> this point. In other words, I don't suspect I have a key/cert problem
> yet :).
>
> I have included the frames in this email. They were captured on the
> radius server side. Note there are two separate attempts from the
> client to authenticate itself. I am questioning either of the Access
> Challenge frames. I would love it if someone could look at these frames
> and tell me if they are correct (that freeradius is creating them properly).
>
> Below the message Authenticator is similar to 0x000000000000000000. In
> the frame sent to the supplicant, the second portion EAP type 79 does
> not have the authenticator, the first portion EAP type 79 does have the
> Message Authenticator and is filled with a value other then
> 0x000000000..... I am guessing that is where the hash for the password
> goes.
>
> Any help would be greatly appreciated.
>
> Here is the output of radiusd -Xxx
>
> Tue Nov 18 14:52:33 2003 : Info: Starting - reading configuration files ...
> Tue Nov 18 14:52:33 2003 : Debug: reread_config: reading radiusd.conf
> Tue Nov 18 14:52:33 2003 : Debug: Config: including file:
> /usr/local/etc/raddb/clients.conf
> Tue Nov 18 14:52:33 2003 : Debug: Config: including file:
> /usr/local/etc/raddb/snmp.conf
> Tue Nov 18 14:52:33 2003 : Debug: main: prefix = "/usr/local"
> Tue Nov 18 14:52:33 2003 : Debug: main: localstatedir = "/usr/local/var"
> Tue Nov 18 14:52:33 2003 : Debug: main: logdir = "/var/log/radius"
> Tue Nov 18 14:52:33 2003 : Debug: main: libdir = "/usr/local/lib"
> Tue Nov 18 14:52:33 2003 : Debug: main: radacctdir =
> "/var/log/radius/radacct"
> Tue Nov 18 14:52:33 2003 : Debug: main: hostname_lookups = no
> Tue Nov 18 14:52:33 2003 : Debug: main: max_request_time = 30
> Tue Nov 18 14:52:33 2003 : Debug: main: cleanup_delay = 5
> Tue Nov 18 14:52:33 2003 : Debug: main: max_requests = 1024
> Tue Nov 18 14:52:33 2003 : Debug: main: delete_blocked_requests = 0
> Tue Nov 18 14:52:33 2003 : Debug: main: port = 0
> Tue Nov 18 14:52:33 2003 : Debug: main: allow_core_dumps = no
> Tue Nov 18 14:52:33 2003 : Debug: main: log_stripped_names = no
> Tue Nov 18 14:52:33 2003 : Debug: main: log_file =
> "/var/log/radius/radius.log"
> Tue Nov 18 14:52:33 2003 : Debug: main: log_auth = yes
> Tue Nov 18 14:52:33 2003 : Debug: main: log_auth_badpass = yes
> Tue Nov 18 14:52:33 2003 : Debug: main: log_auth_goodpass = no
> Tue Nov 18 14:52:33 2003 : Debug: main: pidfile =
> "/usr/local/var/run/radiusd/radiusd.pid"
> Tue Nov 18 14:52:33 2003 : Debug: main: user = "(null)"
> Tue Nov 18 14:52:33 2003 : Debug: main: group = "(null)"
> Tue Nov 18 14:52:33 2003 : Debug: main: usercollide = yes
> Tue Nov 18 14:52:33 2003 : Debug: main: lower_user = "before"
> Tue Nov 18 14:52:33 2003 : Debug: main: lower_pass = "no"
> Tue Nov 18 14:52:33 2003 : Debug: main: nospace_user = "no"
> Tue Nov 18 14:52:33 2003 : Debug: main: nospace_pass = "no"
> Tue Nov 18 14:52:33 2003 : Debug: main: checkrad =
> "/usr/local/sbin/checkrad"
> Tue Nov 18 14:52:33 2003 : Debug: main: proxy_requests = no
> Tue Nov 18 14:52:33 2003 : Debug: security: max_attributes = 200
> Tue Nov 18 14:52:33 2003 : Debug: security: reject_delay = 1
> Tue Nov 18 14:52:33 2003 : Debug: security: status_server = no
> Tue Nov 18 14:52:33 2003 : Debug: main: debug_level = 0
> Tue Nov 18 14:52:33 2003 : Debug: read_config_files: reading dictionary
> Tue Nov 18 14:52:34 2003 : Debug: read_config_files: reading naslist
> Tue Nov 18 14:52:34 2003 : Info: Using deprecated naslist file. Support
> for this will go away soon.
> Tue Nov 18 14:52:34 2003 : Debug: read_config_files: reading clients
> Tue Nov 18 14:52:34 2003 : Debug: read_config_files: reading realms
> Tue Nov 18 14:52:34 2003 : Info: Using deprecated realms file. Support
> for this will go away soon.
> Tue Nov 18 14:52:34 2003 : Debug: radiusd: entering modules setup
> Tue Nov 18 14:52:34 2003 : Debug: Module: Library search path is
> /usr/local/lib
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded expr
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated expr (expr)
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded eap
> Tue Nov 18 14:52:34 2003 : Debug: eap: default_eap_type = "peap"
> Tue Nov 18 14:52:34 2003 : Debug: eap: timer_expire = 60
> Tue Nov 18 14:52:34 2003 : Debug: eap: ignore_unknown_eap_types = no
> Tue Nov 18 14:52:34 2003 : Debug: tls: rsa_key_exchange = no
> Tue Nov 18 14:52:34 2003 : Debug: tls: dh_key_exchange = yes
> Tue Nov 18 14:52:34 2003 : Debug: tls: rsa_key_length = 512
> Tue Nov 18 14:52:34 2003 : Debug: tls: dh_key_length = 512
> Tue Nov 18 14:52:34 2003 : Debug: tls: verify_depth = 0
> Tue Nov 18 14:52:34 2003 : Debug: tls: CA_path =
> "/usr/local/etc/raddb/cert/demoCA"
> Tue Nov 18 14:52:34 2003 : Debug: tls: pem_file_type = yes
> Tue Nov 18 14:52:34 2003 : Debug: tls: private_key_file =
> "/usr/local/etc/raddb/hotspot.ntelos.net.key"
> Tue Nov 18 14:52:34 2003 : Debug: tls: certificate_file =
> "/usr/local/etc/raddb/hotspot.ntelos.net.crt"
> Tue Nov 18 14:52:34 2003 : Debug: tls: CA_file =
> "/usr/local/etc/raddb/ntelos.cacrt"
> Tue Nov 18 14:52:34 2003 : Debug: tls: private_key_password = "testtest"
> Tue Nov 18 14:52:34 2003 : Debug: tls: dh_file =
> "/usr/local/etc/raddb/my_imap.dh"
> Tue Nov 18 14:52:34 2003 : Debug: tls: random_file =
> "/usr/local/etc/raddb/random"
> Tue Nov 18 14:52:34 2003 : Debug: tls: fragment_size = 1024
> Tue Nov 18 14:52:34 2003 : Debug: tls: include_length = no
> Tue Nov 18 14:52:34 2003 : Debug: tls: check_crl = no
> Tue Nov 18 14:52:34 2003 : Debug: rlm_eap: Loaded and initialized type tls
> Tue Nov 18 14:52:34 2003 : Debug: peap: default_eap_type = "mschapv2"
> Tue Nov 18 14:52:34 2003 : Debug: peap: copy_request_to_tunnel = no
> Tue Nov 18 14:52:34 2003 : Debug: peap: use_tunneled_reply = no
> Tue Nov 18 14:52:34 2003 : Debug: rlm_eap: Loaded and initialized type peap
> Tue Nov 18 14:52:34 2003 : Debug: rlm_eap: Loaded and initialized type
> mschapv2
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated eap (eap)
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded PAP
> Tue Nov 18 14:52:34 2003 : Debug: pap: encryption_scheme = "crypt"
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated pap (pap)
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded CHAP
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated chap (chap)
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded MS-CHAP
> Tue Nov 18 14:52:34 2003 : Debug: mschap: use_mppe = yes
> Tue Nov 18 14:52:34 2003 : Debug: mschap: require_encryption = no
> Tue Nov 18 14:52:34 2003 : Debug: mschap: require_strong = yes
> Tue Nov 18 14:52:34 2003 : Debug: mschap: passwd = "(null)"
> Tue Nov 18 14:52:34 2003 : Debug: mschap: authtype = "MS-CHAP"
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated mschap (mschap)
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded preprocess
> Tue Nov 18 14:52:34 2003 : Debug: preprocess: huntgroups =
> "/usr/local/etc/raddb/huntgroups"
> Tue Nov 18 14:52:34 2003 : Debug: preprocess: hints =
> "/usr/local/etc/raddb/hints"
> Tue Nov 18 14:52:34 2003 : Debug: preprocess: with_ascend_hack = no
> Tue Nov 18 14:52:34 2003 : Debug: preprocess: ascend_channels_per_line = 23
> Tue Nov 18 14:52:34 2003 : Debug: preprocess: with_ntdomain_hack = yes
> Tue Nov 18 14:52:34 2003 : Debug: preprocess:
> with_specialix_jetstream_hack = no
> Tue Nov 18 14:52:34 2003 : Debug: preprocess: with_cisco_vsa_hack = yes
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated preprocess
> (preprocess)
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded detail
> Tue Nov 18 14:52:34 2003 : Debug: detail: detailfile =
> "/var/log/radius/radacct/%{Client-IP-Address}/auth-detail
> -%Y%m%d"
> Tue Nov 18 14:52:34 2003 : Debug: detail: detailperm = 384
> Tue Nov 18 14:52:34 2003 : Debug: detail: dirperm = 493
> Tue Nov 18 14:52:34 2003 : Debug: detail: locking = no
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated detail (auth_log)
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded realm
> Tue Nov 18 14:52:34 2003 : Debug: realm: format = "suffix"
> Tue Nov 18 14:52:34 2003 : Debug: realm: delimiter = "@"
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated realm (suffix)
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded files
> Tue Nov 18 14:52:34 2003 : Debug: files: usersfile =
> "/usr/local/etc/raddb/users"
> Tue Nov 18 14:52:34 2003 : Debug: files: acctusersfile =
> "/usr/local/etc/raddb/acct_users"
> Tue Nov 18 14:52:34 2003 : Debug: files: preproxy_usersfile =
> "/usr/local/etc/raddb/preproxy_users"
> Tue Nov 18 14:52:34 2003 : Debug: files: compat = "no"
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated files (files)
> Tue Nov 18 14:52:34 2003 : Debug: Module: Loaded Acct-Unique-Session-Id
> Tue Nov 18 14:52:34 2003 : Debug: acct_unique: key = "User-Name,
> Acct-Session-Id, NAS-IP-Address, Client-IP-Addr
> ess, NAS-Port-Id"
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated acct_unique
> (acct_unique)
> Tue Nov 18 14:52:34 2003 : Debug: detail: detailfile =
> "/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m
> %d"
> Tue Nov 18 14:52:34 2003 : Debug: detail: detailperm = 384
> Tue Nov 18 14:52:34 2003 : Debug: detail: dirperm = 493
> Tue Nov 18 14:52:34 2003 : Debug: detail: locking = no
> Tue Nov 18 14:52:34 2003 : Debug: Module: Instantiated detail (detail)
> Tue Nov 18 14:52:34 2003 : Info: Listening on IP address *, ports
> 1812/udp and 1813/udp.
> Tue Nov 18 14:52:34 2003 : Info: Ready to process requests.
> rad_recv: Access-Request packet from host xxx.xx.xx.xx:3478, id=0,
> length=151
> User-Name = "wer"
> Cisco-AVPair = "ssid=Ntelos_AP_01"
> NAS-IP-Address = xxx.xx.xx.30
> Called-Station-Id = "000dbda1f1e9"
> Calling-Station-Id = "000dbd05196d"
> NAS-Identifier = "AP1200-a1f1e9"
> NAS-Port = 37
> Framed-MTU = 1400
> NAS-Port-Type = Wireless-802.11
> Service-Type = Login-User
> EAP-Message = 0x0204000801776572
> Message-Authenticator = 0xd2b26a05cb73ad0a4fc147eb2d3185cb
> Tue Nov 18 16:27:46 2003 : Debug: rad_lowerpair: User-Name now 'wer'
> Tue Nov 18 16:27:46 2003 : Debug: modcall: entering group authorize for
> request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: calling
> preprocess (rlm_preprocess) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: returned from
> preprocess (rlm_preprocess) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall[authorize]: module
> "preprocess" returns ok for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: calling
> auth_log (rlm_detail) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: radius_xlat:
> '/var/log/radius/radacct/209.145.66.30/auth-detail-20031118'
> Tue Nov 18 16:27:46 2003 : Debug: rlm_detail:
> /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d exp
> ands to /var/log/radius/radacct/209.145.66.30/auth-detail-20031118
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: returned from
> auth_log (rlm_detail) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall[authorize]: module
> "auth_log" returns ok for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: calling chap
> (rlm_chap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: returned from
> chap (rlm_chap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall[authorize]: module "chap"
> returns noop for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: calling eap
> (rlm_eap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap: EAP packet type response id
> 4 length 8
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap: No EAP Start, assuming it's
> an on-going EAP conversation
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: returned from
> eap (rlm_eap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall[authorize]: module "eap"
> returns updated for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: calling suffix
> (rlm_realm) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: rlm_realm: No '@' in User-Name =
> "wer", looking up realm NULL
> Tue Nov 18 16:27:46 2003 : Debug: rlm_realm: No such realm "NULL"
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: returned from
> suffix (rlm_realm) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall[authorize]: module "suffix"
> returns noop for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: calling files
> (rlm_files) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: users: Checking wer at 107
> Tue Nov 18 16:27:46 2003 : Debug: rad_check_password: Found Auth-Type EAP
> Tue Nov 18 16:27:46 2003 : Debug: auth: type "EAP"
> Tue Nov 18 16:27:46 2003 : Debug: modcall: entering group authenticate
> for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authenticate]: calling eap
> (rlm_eap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap: EAP Identity
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap: processing type tls
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap_tls: Initiate
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap_tls: Start returned 1
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authenticate]: returned
> from eap (rlm_eap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall[authenticate]: module "eap"
> returns handled for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall: group authenticate returns
> handled for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: returned from
> files (rlm_files) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall[authorize]: module "files"
> returns notfound for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: calling mschap
> (rlm_mschap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authorize]: returned from
> mschap (rlm_mschap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall[authorize]: module "mschap"
> returns noop for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall: group authorize returns
> updated for request 0
> Tue Nov 18 16:27:46 2003 : Debug: rad_check_password: Found Auth-Type EAP
> Tue Nov 18 16:27:46 2003 : Debug: auth: type "EAP"
> Tue Nov 18 16:27:46 2003 : Debug: modcall: entering group authenticate
> for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authenticate]: calling eap
> (rlm_eap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap: EAP Identity
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap: processing type tls
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap_tls: Initiate
> Tue Nov 18 16:27:46 2003 : Debug: rlm_eap_tls: Start returned 1
> Tue Nov 18 16:27:46 2003 : Debug: modsingle[authenticate]: returned
> from eap (rlm_eap) for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall[authenticate]: module "eap"
> returns ok for request 0
> Tue Nov 18 16:27:46 2003 : Debug: modcall: group authenticate returns ok
> for request 0
> Tue Nov 18 16:27:46 2003 : Auth: Login OK: [wer] (from client vxworks
> port 37 cli 000dbd05196d)
> Sending Access-Challenge of id 0 to xxx.xx.xx.30:3478
> EAP-Message = 0x010500061920
> Message-Authenticator = 0x00000000000000000000000000000000
> State = 0xdb2f1835ce2a00e92bb9c03a9c402f16
> EAP-Message = 0x010500061920
> State = 0xc0efdbdc7e50636cfbd37c5abdafdbbb
> Tue Nov 18 16:27:46 2003 : Debug: Finished request 0
> Tue Nov 18 16:27:46 2003 : Debug: Going to the next request
> Tue Nov 18 16:27:46 2003 : Debug: --- Walking the entire request list ---
> Tue Nov 18 16:27:46 2003 : Debug: Waking up in 6 seconds...
> Tue Nov 18 16:27:52 2003 : Debug: --- Walking the entire request list ---
> Tue Nov 18 16:27:52 2003 : Debug: Cleaning up request 0 ID 0 with
> timestamp 3fba8ed2
> Tue Nov 18 16:27:52 2003 : Debug: Nothing to do. Sleeping until we see
> a request.
--
--Mike
-----------------------------------
Michael Griego
Wireless LAN Project Manager
The University of Texas at Dallas
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
