Flaky AP or borked Config? EAP-PEAP

17 Aug 2010

      Due to some Skypilot APs that do not support EAP-TLS (requiring client certs) i am working on getting tunneled peap happening, authenticating against AD. After following the excellent READMEs and other instructional material at deployingradius and freeradius.org
I have a successful configuration that access-accept's with EAP-TLS as well as cleartext passwords. My homegrown certs work well with my AP (a cisco 1130AG for testing) and EAP-TLS, but i cannot get an access-accept with tunneled peap. A bad password will return access-reject, pap logins work, but a good AD login gets stuck at an access-challenge. 

I have not mucked around with the default configs, only adding specifics where required. EAP-TLS, PAP work, but no EAP-PEAP, ntlm_auth works from the command line (debug appears to show mschapv2 success)

Thank you for taking the time,
debug output below

/etc/freeradius# freeradius -XXX
Tue Aug 17 15:10:47 2010 : Info: FreeRADIUS Version 2.1.8, for host i486-pc-linux-gnu, built on May 21 2010 at 19:08:55
Tue Aug 17 15:10:47 2010 : Info: Copyright (C) 1999-2009 The FreeRADIUS server project and contributors.
Tue Aug 17 15:10:47 2010 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Tue Aug 17 15:10:47 2010 : Info: PARTICULAR PURPOSE.
Tue Aug 17 15:10:47 2010 : Info: You may redistribute copies of FreeRADIUS under the terms of the
Tue Aug 17 15:10:47 2010 : Info: GNU General Public License v2.
Tue Aug 17 15:10:47 2010 : Info: Starting - reading configuration files ...
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/radiusd.conf
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/clients.conf
Tue Aug 17 15:10:47 2010 : Debug: including files in directory /etc/freeradius/modules/
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/attr_filter
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/mac2ip
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/expr
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/radutmp
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/counter
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/krb5
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/detail.log
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/inner-eap
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/detail
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/etc_group
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/sqlcounter_expire_on_login
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/checkval
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/perl
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/digest
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/ldap
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/smsotp
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/exec
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/detail.example.com
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/ntlm_auth
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/linelog
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/expiration
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/logintime
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/acct_unique
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/chap
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/unix
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/attr_rewrite
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/ippool
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/realm
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/files
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/smbpasswd
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/pap
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/echo
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/pam
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/wimax
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/preprocess
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/sql_log
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/always
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/policy
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/mschap
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/cui
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/mac2vlan
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/sradutmp
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/passwd
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/modules/otp
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/eap.conf
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/policy.conf
Tue Aug 17 15:10:47 2010 : Debug: including files in directory /etc/freeradius/sites-enabled/
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/sites-enabled/default
Tue Aug 17 15:10:47 2010 : Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel
Tue Aug 17 15:10:47 2010 : Debug: main {
Tue Aug 17 15:10:47 2010 : Debug:       user = "freerad"
Tue Aug 17 15:10:47 2010 : Debug:       group = "freerad"
Tue Aug 17 15:10:47 2010 : Debug:       allow_core_dumps = no
Tue Aug 17 15:10:47 2010 : Debug: }
Tue Aug 17 15:10:47 2010 : Debug: including dictionary file /etc/freeradius/dictionary
Tue Aug 17 15:10:47 2010 : Debug: main {
Tue Aug 17 15:10:47 2010 : Debug:       prefix = "/usr"
Tue Aug 17 15:10:47 2010 : Debug:       localstatedir = "/var"
Tue Aug 17 15:10:47 2010 : Debug:       logdir = "/var/log/freeradius"
Tue Aug 17 15:10:47 2010 : Debug:       libdir = "/usr/lib/freeradius"
Tue Aug 17 15:10:47 2010 : Debug:       radacctdir = "/var/log/freeradius/radacct"
Tue Aug 17 15:10:47 2010 : Debug:       hostname_lookups = no
Tue Aug 17 15:10:47 2010 : Debug:       max_request_time = 30
Tue Aug 17 15:10:47 2010 : Debug:       cleanup_delay = 5
Tue Aug 17 15:10:47 2010 : Debug:       max_requests = 1024
Tue Aug 17 15:10:47 2010 : Debug:       pidfile = "/var/run/freeradius/freeradius.pid"
Tue Aug 17 15:10:47 2010 : Debug:       checkrad = "/usr/sbin/checkrad"
Tue Aug 17 15:10:47 2010 : Debug:       debug_level = 0
Tue Aug 17 15:10:47 2010 : Debug:       proxy_requests = no
Tue Aug 17 15:10:47 2010 : Debug:  log {
Tue Aug 17 15:10:47 2010 : Debug:       stripped_names = yes
Tue Aug 17 15:10:47 2010 : Debug:       auth = yes
Tue Aug 17 15:10:47 2010 : Debug:       auth_badpass = yes
Tue Aug 17 15:10:47 2010 : Debug:       auth_goodpass = no
Tue Aug 17 15:10:47 2010 : Debug:  }
Tue Aug 17 15:10:47 2010 : Debug:  security {
Tue Aug 17 15:10:47 2010 : Debug:       max_attributes = 200
Tue Aug 17 15:10:47 2010 : Debug:       reject_delay = 1
Tue Aug 17 15:10:47 2010 : Debug:       status_server = yes
Tue Aug 17 15:10:47 2010 : Debug:  }
Tue Aug 17 15:10:47 2010 : Debug: }
Tue Aug 17 15:10:47 2010 : Debug: radiusd: #### Loading Realms and Home Servers ####
Tue Aug 17 15:10:47 2010 : Debug: radiusd: #### Loading Clients ####
Tue Aug 17 15:10:47 2010 : Debug:  client localhost {
Tue Aug 17 15:10:47 2010 : Debug:       ipaddr = 127.0.0.1
Tue Aug 17 15:10:47 2010 : Debug:       require_message_authenticator = no
Tue Aug 17 15:10:47 2010 : Debug:       secret = "XXXXXXX"
Tue Aug 17 15:10:47 2010 : Debug:       nastype = "other"
Tue Aug 17 15:10:47 2010 : Debug:  }
Tue Aug 17 15:10:47 2010 : Debug:  client 10.10.9.253 {
Tue Aug 17 15:10:47 2010 : Debug:       require_message_authenticator = no
Tue Aug 17 15:10:47 2010 : Debug:       secret = "XXXXXXX"
Tue Aug 17 15:10:47 2010 : Debug:       shortname = "misAP"
Tue Aug 17 15:10:47 2010 : Debug:  }
Tue Aug 17 15:10:47 2010 : Debug:  client 10.11.100.0/24 {
Tue Aug 17 15:10:47 2010 : Debug:       require_message_authenticator = no
Tue Aug 17 15:10:47 2010 : Debug:       secret = "XXXXXXX"
Tue Aug 17 15:10:47 2010 : Debug:       shortname = "mainofficeAP"
Tue Aug 17 15:10:47 2010 : Debug:  }
Tue Aug 17 15:10:47 2010 : Debug:  client 10.30.0.0/16 {
Tue Aug 17 15:10:47 2010 : Debug:       require_message_authenticator = no
Tue Aug 17 15:10:47 2010 : Debug:       secret = "XXXXXX"
Tue Aug 17 15:10:47 2010 : Debug:       shortname = "mnwman"
Tue Aug 17 15:10:47 2010 : Debug:       nastype = "other"
Tue Aug 17 15:10:47 2010 : Debug:  }
Tue Aug 17 15:10:47 2010 : Debug:  client 192.168.7.2 {
Tue Aug 17 15:10:47 2010 : Debug:       require_message_authenticator = no
Tue Aug 17 15:10:47 2010 : Debug:       secret = "XXXXXX"
Tue Aug 17 15:10:47 2010 : Debug:       shortname = "vpn3k"
Tue Aug 17 15:10:47 2010 : Debug:       nastype = "cisco"
Tue Aug 17 15:10:47 2010 : Debug:  }
Tue Aug 17 15:10:47 2010 : Debug:  client 10.10.100.0/24 {
Tue Aug 17 15:10:47 2010 : Debug:       require_message_authenticator = no
Tue Aug 17 15:10:47 2010 : Debug:       secret = "XXXXXXX"
Tue Aug 17 15:10:47 2010 : Debug:       shortname = "2A_Aps"
Tue Aug 17 15:10:47 2010 : Debug:  }
Tue Aug 17 15:10:47 2010 : Debug: radiusd: #### Instantiating modules ####
Tue Aug 17 15:10:47 2010 : Debug:  instantiate {
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_exec, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_exec
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating exec
Tue Aug 17 15:10:47 2010 : Debug:   exec {
Tue Aug 17 15:10:47 2010 : Debug:       wait = no
Tue Aug 17 15:10:47 2010 : Debug:       input_pairs = "request"
Tue Aug 17 15:10:47 2010 : Debug:       shell_escape = yes
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_expr, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_expr
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating expr
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_expiration, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_expiration
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating expiration
Tue Aug 17 15:10:47 2010 : Debug:   expiration {
Tue Aug 17 15:10:47 2010 : Debug:       reply-message = "Password Has Expired  "
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_logintime, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_logintime
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating logintime
Tue Aug 17 15:10:47 2010 : Debug:   logintime {
Tue Aug 17 15:10:47 2010 : Debug:       reply-message = "You are calling outside your allowed timespan  "
Tue Aug 17 15:10:47 2010 : Debug:       minimum-timeout = 60
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  }
Tue Aug 17 15:10:47 2010 : Debug: radiusd: #### Loading Virtual Servers ####
Tue Aug 17 15:10:47 2010 : Debug: server inner-tunnel {
Tue Aug 17 15:10:47 2010 : Debug:  modules {
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking authenticate {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_pap, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_pap
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating pap
Tue Aug 17 15:10:47 2010 : Debug:   pap {
Tue Aug 17 15:10:47 2010 : Debug:       encryption_scheme = "auto"
Tue Aug 17 15:10:47 2010 : Debug:       auto_header = no
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_chap, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_chap
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating chap
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_mschap, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_mschap
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating mschap
Tue Aug 17 15:10:47 2010 : Debug:   mschap {
Tue Aug 17 15:10:47 2010 : Debug:       use_mppe = no
Tue Aug 17 15:10:47 2010 : Debug:       require_encryption = yes
Tue Aug 17 15:10:47 2010 : Debug:       require_strong = yes
Tue Aug 17 15:10:47 2010 : Debug:       with_ntdomain_hack = no
Tue Aug 17 15:10:47 2010 : Debug:       ntlm_auth = "/usr/bin/ntlm_auth --request-nt-key --username=%{%{Stripped-User-Name}:-%{User-Name:-None}} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}"
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_unix, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_unix
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating unix
Tue Aug 17 15:10:47 2010 : Debug:   unix {
Tue Aug 17 15:10:47 2010 : Debug:       radwtmp = "/var/log/freeradius/radwtmp"
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_eap, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_eap
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating eap
Tue Aug 17 15:10:47 2010 : Debug:   eap {
Tue Aug 17 15:10:47 2010 : Debug:       default_eap_type = "peap"
Tue Aug 17 15:10:47 2010 : Debug:       timer_expire = 60
Tue Aug 17 15:10:47 2010 : Debug:       ignore_unknown_eap_types = no
Tue Aug 17 15:10:47 2010 : Debug:       cisco_accounting_username_bug = no
Tue Aug 17 15:10:47 2010 : Debug:       max_sessions = 4096
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to sub-module rlm_eap_md5
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating eap-md5
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to sub-module rlm_eap_leap
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating eap-leap
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to sub-module rlm_eap_gtc
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating eap-gtc
Tue Aug 17 15:10:47 2010 : Debug:    gtc {
Tue Aug 17 15:10:47 2010 : Debug:       challenge = "Password: "
Tue Aug 17 15:10:47 2010 : Debug:       auth_type = "PAP"
Tue Aug 17 15:10:47 2010 : Debug:    }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to sub-module rlm_eap_tls
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating eap-tls
Tue Aug 17 15:10:47 2010 : Debug:    tls {
Tue Aug 17 15:10:47 2010 : Debug:       rsa_key_exchange = no
Tue Aug 17 15:10:47 2010 : Debug:       dh_key_exchange = yes
Tue Aug 17 15:10:47 2010 : Debug:       rsa_key_length = 512
Tue Aug 17 15:10:47 2010 : Debug:       dh_key_length = 512
Tue Aug 17 15:10:47 2010 : Debug:       verify_depth = 0
Tue Aug 17 15:10:47 2010 : Debug:       pem_file_type = yes
Tue Aug 17 15:10:47 2010 : Debug:       private_key_file = "/etc/freeradius/certs/safe/server.pem"
Tue Aug 17 15:10:47 2010 : Debug:       certificate_file = "/etc/freeradius/certs/safe/server.pem"
Tue Aug 17 15:10:47 2010 : Debug:       CA_file = "/etc/freeradius/certs/ca.pem"
Tue Aug 17 15:10:47 2010 : Debug:       private_key_password = "moulton2010securewifi"
Tue Aug 17 15:10:47 2010 : Debug:       dh_file = "/etc/freeradius/certs/dh"
Tue Aug 17 15:10:47 2010 : Debug:       random_file = "/etc/freeradius/certs/random"
Tue Aug 17 15:10:47 2010 : Debug:       fragment_size = 1024
Tue Aug 17 15:10:47 2010 : Debug:       include_length = yes
Tue Aug 17 15:10:47 2010 : Debug:       check_crl = no
Tue Aug 17 15:10:47 2010 : Debug:       cipher_list = "DEFAULT"
Tue Aug 17 15:10:47 2010 : Debug:       make_cert_command = "/etc/freeradius/certs/bootstrap"
Tue Aug 17 15:10:47 2010 : Debug:     cache {
Tue Aug 17 15:10:47 2010 : Debug:       enable = no
Tue Aug 17 15:10:47 2010 : Debug:       lifetime = 24
Tue Aug 17 15:10:47 2010 : Debug:       max_entries = 255
Tue Aug 17 15:10:47 2010 : Debug:     }
Tue Aug 17 15:10:47 2010 : Debug:    }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to sub-module rlm_eap_ttls
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating eap-ttls
Tue Aug 17 15:10:47 2010 : Debug:    ttls {
Tue Aug 17 15:10:47 2010 : Debug:       default_eap_type = "md5"
Tue Aug 17 15:10:47 2010 : Debug:       copy_request_to_tunnel = no
Tue Aug 17 15:10:47 2010 : Debug:       use_tunneled_reply = no
Tue Aug 17 15:10:47 2010 : Debug:       virtual_server = "inner-tunnel"
Tue Aug 17 15:10:47 2010 : Debug:       include_length = yes
Tue Aug 17 15:10:47 2010 : Debug:    }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to sub-module rlm_eap_peap
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating eap-peap
Tue Aug 17 15:10:47 2010 : Debug:    peap {
Tue Aug 17 15:10:47 2010 : Debug:       default_eap_type = "mschapv2"
Tue Aug 17 15:10:47 2010 : Debug:       copy_request_to_tunnel = no
Tue Aug 17 15:10:47 2010 : Debug:       use_tunneled_reply = no
Tue Aug 17 15:10:47 2010 : Debug:       proxy_tunneled_request_as_eap = yes
Tue Aug 17 15:10:47 2010 : Debug:       virtual_server = "inner-tunnel"
Tue Aug 17 15:10:47 2010 : Debug:    }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to sub-module rlm_eap_mschapv2
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating eap-mschapv2
Tue Aug 17 15:10:47 2010 : Debug:    mschapv2 {
Tue Aug 17 15:10:47 2010 : Debug:       with_ntdomain_hack = no
Tue Aug 17 15:10:47 2010 : Debug:    }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating ntlm_auth
Tue Aug 17 15:10:47 2010 : Debug:   exec ntlm_auth {
Tue Aug 17 15:10:47 2010 : Debug:       wait = yes
Tue Aug 17 15:10:47 2010 : Debug:       program = "/usr/bin/ntlm_auth --request-nt-key --domain=NAS --username=%{mschap:User-Name} --password=%{User-Password}"
Tue Aug 17 15:10:47 2010 : Debug:       input_pairs = "request"
Tue Aug 17 15:10:47 2010 : Debug:       shell_escape = yes
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking authorize {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_files, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_files
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating files
Tue Aug 17 15:10:47 2010 : Debug:   files {
Tue Aug 17 15:10:47 2010 : Debug:       usersfile = "/etc/freeradius/users"
Tue Aug 17 15:10:47 2010 : Debug:       acctusersfile = "/etc/freeradius/acct_users"
Tue Aug 17 15:10:47 2010 : Debug:       preproxy_usersfile = "/etc/freeradius/preproxy_users"
Tue Aug 17 15:10:47 2010 : Debug:       compat = "no"
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking session {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_radutmp, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_radutmp
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating radutmp
Tue Aug 17 15:10:47 2010 : Debug:   radutmp {
Tue Aug 17 15:10:47 2010 : Debug:       filename = "/var/log/freeradius/radutmp"
Tue Aug 17 15:10:47 2010 : Debug:       username = "%{User-Name}"
Tue Aug 17 15:10:47 2010 : Debug:       case_sensitive = yes
Tue Aug 17 15:10:47 2010 : Debug:       check_with_nas = yes
Tue Aug 17 15:10:47 2010 : Debug:       perm = 384
Tue Aug 17 15:10:47 2010 : Debug:       callerid = yes
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking post-proxy {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking post-auth {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_attr_filter, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_attr_filter
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating attr_filter.access_reject
Tue Aug 17 15:10:47 2010 : Debug:   attr_filter attr_filter.access_reject {
Tue Aug 17 15:10:47 2010 : Debug:       attrsfile = "/etc/freeradius/attrs.access_reject"
Tue Aug 17 15:10:47 2010 : Debug:       key = "%{User-Name}"
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  } # modules
Tue Aug 17 15:10:47 2010 : Debug: } # server
Tue Aug 17 15:10:47 2010 : Debug: server {
Tue Aug 17 15:10:47 2010 : Debug:  modules {
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking authenticate {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_digest, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_digest
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating digest
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking authorize {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_preprocess, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_preprocess
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating preprocess
Tue Aug 17 15:10:47 2010 : Debug:   preprocess {
Tue Aug 17 15:10:47 2010 : Debug:       huntgroups = "/etc/freeradius/huntgroups"
Tue Aug 17 15:10:47 2010 : Debug:       hints = "/etc/freeradius/hints"
Tue Aug 17 15:10:47 2010 : Debug:       with_ascend_hack = no
Tue Aug 17 15:10:47 2010 : Debug:       ascend_channels_per_line = 23
Tue Aug 17 15:10:47 2010 : Debug:       with_ntdomain_hack = no
Tue Aug 17 15:10:47 2010 : Debug:       with_specialix_jetstream_hack = no
Tue Aug 17 15:10:47 2010 : Debug:       with_cisco_vsa_hack = no
Tue Aug 17 15:10:47 2010 : Debug:       with_alvarion_vsa_hack = no
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking preacct {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_acct_unique, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_acct_unique
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating acct_unique
Tue Aug 17 15:10:47 2010 : Debug:   acct_unique {
Tue Aug 17 15:10:47 2010 : Debug:       key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_realm, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_realm
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating suffix
Tue Aug 17 15:10:47 2010 : Debug:   realm suffix {
Tue Aug 17 15:10:47 2010 : Debug:       format = "suffix"
Tue Aug 17 15:10:47 2010 : Debug:       delimiter = "@"
Tue Aug 17 15:10:47 2010 : Debug:       ignore_default = no
Tue Aug 17 15:10:47 2010 : Debug:       ignore_null = no
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking accounting {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:     (Loaded rlm_detail, checking if it's valid)
Tue Aug 17 15:10:47 2010 : Debug:  Module: Linked to module rlm_detail
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating detail
Tue Aug 17 15:10:47 2010 : Debug:   detail {
Tue Aug 17 15:10:47 2010 : Debug:       detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Tue Aug 17 15:10:47 2010 : Debug:       header = "%t"
Tue Aug 17 15:10:47 2010 : Debug:       detailperm = 384
Tue Aug 17 15:10:47 2010 : Debug:       dirperm = 493
Tue Aug 17 15:10:47 2010 : Debug:       locking = no
Tue Aug 17 15:10:47 2010 : Debug:       log_packet_header = no
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Instantiating attr_filter.accounting_response
Tue Aug 17 15:10:47 2010 : Debug:   attr_filter attr_filter.accounting_response {
Tue Aug 17 15:10:47 2010 : Debug:       attrsfile = "/etc/freeradius/attrs.accounting_response"
Tue Aug 17 15:10:47 2010 : Debug:       key = "%{User-Name}"
Tue Aug 17 15:10:47 2010 : Debug:   }
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking session {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking post-proxy {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:  Module: Checking post-auth {...} for more modules to load
Tue Aug 17 15:10:47 2010 : Debug:  } # modules
Tue Aug 17 15:10:47 2010 : Debug: } # server
Tue Aug 17 15:10:47 2010 : Debug: radiusd: #### Opening IP addresses and Ports ####
Tue Aug 17 15:10:47 2010 : Debug: listen {
Tue Aug 17 15:10:47 2010 : Debug:       type = "auth"
Tue Aug 17 15:10:47 2010 : Debug:       ipaddr = *
Tue Aug 17 15:10:47 2010 : Debug:       port = 0
Tue Aug 17 15:10:47 2010 : Debug: }
Tue Aug 17 15:10:47 2010 : Debug: listen {
Tue Aug 17 15:10:47 2010 : Debug:       type = "acct"
Tue Aug 17 15:10:47 2010 : Debug:       ipaddr = *
Tue Aug 17 15:10:47 2010 : Debug:       port = 0
Tue Aug 17 15:10:47 2010 : Debug: }
Tue Aug 17 15:10:47 2010 : Debug: listen {
Tue Aug 17 15:10:47 2010 : Debug:       type = "auth"
Tue Aug 17 15:10:47 2010 : Debug:       ipaddr = 127.0.0.1
Tue Aug 17 15:10:47 2010 : Debug:       port = 18120
Tue Aug 17 15:10:47 2010 : Debug: }
Tue Aug 17 15:10:47 2010 : Debug: Listening on authentication address * port 1812
Tue Aug 17 15:10:47 2010 : Debug: Listening on accounting address * port 1813
Tue Aug 17 15:10:47 2010 : Debug: Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel
Tue Aug 17 15:10:47 2010 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 10.10.100.5 port 1645, id=13, length=132
        User-Name = "nking"
        Framed-MTU = 1400
        Called-Station-Id = "0021.a0f9.5121"
        Calling-Station-Id = "0013.0245.ab2a"
        Service-Type = Login-User
        Message-Authenticator = 0xe9afe31fab46e56b14c3efa330dd113e
        EAP-Message = 0x0202000a016e6b696e67
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 611
        NAS-Port-Id = "611"
        NAS-IP-Address = 10.10.100.5
        NAS-Identifier = "OPSap1"
Tue Aug 17 15:12:04 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:04 2010 : Info: ++[preprocess] returns ok
Tue Aug 17 15:12:04 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:04 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP packet type response id 2 length 10
Tue Aug 17 15:12:04 2010 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns updated
Tue Aug 17 15:12:04 2010 : Info: ++[files] returns noop
Tue Aug 17 15:12:04 2010 : Info: ++[expiration] returns noop
Tue Aug 17 15:12:04 2010 : Info: ++[logintime] returns noop
Tue Aug 17 15:12:04 2010 : Info: [pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Tue Aug 17 15:12:04 2010 : Info: ++[pap] returns noop
Tue Aug 17 15:12:04 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:04 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP Identity
Tue Aug 17 15:12:04 2010 : Info: [eap] processing type tls
Tue Aug 17 15:12:04 2010 : Info: [tls] Initiate
Tue Aug 17 15:12:04 2010 : Info: [tls] Start returned 1
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns handled
Sending Access-Challenge of id 13 to 10.10.100.5 port 1645
        EAP-Message = 0x010300061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd4b1f85ad4b2e16d5a9aa79773704d28
Tue Aug 17 15:12:04 2010 : Info: Finished request 0.
Tue Aug 17 15:12:04 2010 : Debug: Going to the next request
Tue Aug 17 15:12:04 2010 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.10.100.5 port 1645, id=14, length=220
        User-Name = "nking"
        Framed-MTU = 1400
        Called-Station-Id = "0021.a0f9.5121"
        Calling-Station-Id = "0013.0245.ab2a"
        Service-Type = Login-User
        Message-Authenticator = 0xebbd3aace1599a676323ca06077d45cd
        EAP-Message = 0x0203005019800000004616030100410100003d03014c6b092eef882b521ed7071febe6ad5eb5fb913f9e13ce745b00979ff08b788900001600040005000a000900640062000300060013001200630100
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 611
        NAS-Port-Id = "611"
        State = 0xd4b1f85ad4b2e16d5a9aa79773704d28
        NAS-IP-Address = 10.10.100.5
        NAS-Identifier = "OPSap1"
Tue Aug 17 15:12:04 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:04 2010 : Info: ++[preprocess] returns ok
Tue Aug 17 15:12:04 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:04 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP packet type response id 3 length 80
Tue Aug 17 15:12:04 2010 : Info: [eap] Continuing tunnel setup.
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns ok
Tue Aug 17 15:12:04 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:04 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:04 2010 : Info: [eap] Request found, released from the list
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP/peap
Tue Aug 17 15:12:04 2010 : Info: [eap] processing type peap
Tue Aug 17 15:12:04 2010 : Info: [peap] processing EAP-TLS
Tue Aug 17 15:12:04 2010 : Debug:   TLS Length 70
Tue Aug 17 15:12:04 2010 : Info: [peap] Length Included
Tue Aug 17 15:12:04 2010 : Info: [peap] eaptls_verify returned 11
Tue Aug 17 15:12:04 2010 : Info: [peap]     (other): before/accept initialization
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: before/accept initialization
Tue Aug 17 15:12:04 2010 : Info: [peap] <<< TLS 1.0 Handshake [length 0041], ClientHello
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 read client hello A
Tue Aug 17 15:12:04 2010 : Info: [peap] >>> TLS 1.0 Handshake [length 002a], ServerHello
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 write server hello A
Tue Aug 17 15:12:04 2010 : Info: [peap] >>> TLS 1.0 Handshake [length 08a0], Certificate
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 write certificate A
Tue Aug 17 15:12:04 2010 : Info: [peap] >>> TLS 1.0 Handshake [length 0004], ServerHelloDone
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 write server done A
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 flush data
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: Need to read more data: SSLv3 read client certificate A
Tue Aug 17 15:12:04 2010 : Debug: In SSL Handshake Phase
Tue Aug 17 15:12:04 2010 : Debug: In SSL Accept mode
Tue Aug 17 15:12:04 2010 : Info: [peap] eaptls_process returned 13
Tue Aug 17 15:12:04 2010 : Info: [peap] EAPTLS_HANDLED
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns handled
Sending Access-Challenge of id 14 to 10.10.100.5 port 1645
        EAP-Message = 0x0104040019c0000008dd160301002a0200002603014c6b09343e06de886c4ce89ff4034338535f058cb2c3a9e9268bcb236fdde1420000040016030108a00b00089c0008990003c5308203c1308202a9a003020102020101300d06092a864886f70d010104050030819e310b3009060355040613025553310b3009060355040813024341310d300b060355040713044d4e574431263024060355040a131d4d6f756c746f6e204e696775656c2057617465722044697374726963743126302406092a864886f70d01090116174d6f756c746f6e537570706f7274406d6e77642e636f6d312330210603550403131a4d4e57442043657274696669636174
        EAP-Message = 0x6520417574686f72697479301e170d3130303630343135343234365a170d3131303630343135343234365a30818f310b3009060355040613025553310b300906035504081302434131263024060355040a131d4d6f756c746f6e204e696775656c205761746572204469737472696374312330210603550403131a4b72616b6b656e205365727665722043657274696669636174653126302406092a864886f70d01090116174d6f756c746f6e537570706f7274406d6e77642e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100af0fc9afeeeba5b7bd3982841ad2e9c415a7b66fa54c2b94648b16add21b55
        EAP-Message = 0x54535ba463fc4b46fa8c914861f0b3c240e5fe21bf75add41762d9dc5610c4bc37a9e5d63bf45c06e32f530ebd67f27ed08e2e7438cdbb8d1d3ac43efe492a69f8be884a17d5ee36a44865fea88b9a2c01e617848793dfc98bc9d6a0c21cc09a01612a854063c518b4adbd5c652bbc9a76b003419a54dd87ee7dd2075914ef9600583e8e75c07825e9390f72e544418b2c34c6f60e1b1d35590414a7eda2cb7f9b96a1c9672a12b70f2c3acc7d03697681d4fb3146e04f89664d1edcc69c61bfad975f3a3b97c3d002068e82b570366400453834a3365b1ffe91030f078f66f4530203010001a317301530130603551d25040c300a06082b0601050507
        EAP-Message = 0x0301300d06092a864886f70d010104050003820101001bdd7627a5fa3df3c8b8e7998c3c1d43063856efb2b777b53475fc036fa04d8f0f5831f715f612b843b97f430300c9ede7c166eeb8399de072fcb41c37703ae492588a80514388ef22190230b2951a396f48a1ed0ac873c1c2adebe155b55445078346a1a75fbecfab85ff2be09e6f3cf2d9797fbf114d2bfca2f6438caeb1ce0011dc607ebef286417d33d6a7c72d34c26ad47e6b61154afa991592379c719e65e9c6da9e9609284cb97554654b7bdbf0b11924d4cd89c8e3f4508022ecae6cde087885c6198c64bb64c52b536f306794e624181e000c0beb831a4eae1701561b954eb135cdcc
        EAP-Message = 0x8375b6dd06ce5a4842b1732a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd4b1f85ad5b5e16d5a9aa79773704d28
Tue Aug 17 15:12:04 2010 : Info: Finished request 1.
Tue Aug 17 15:12:04 2010 : Debug: Going to the next request
Tue Aug 17 15:12:04 2010 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.10.100.5 port 1645, id=15, length=146
        User-Name = "nking"
        Framed-MTU = 1400
        Called-Station-Id = "0021.a0f9.5121"
        Calling-Station-Id = "0013.0245.ab2a"
        Service-Type = Login-User
        Message-Authenticator = 0xe55971af47959a9500cf6925902530e9
        EAP-Message = 0x020400061900
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 611
        NAS-Port-Id = "611"
        State = 0xd4b1f85ad5b5e16d5a9aa79773704d28
        NAS-IP-Address = 10.10.100.5
        NAS-Identifier = "OPSap1"
Tue Aug 17 15:12:04 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:04 2010 : Info: ++[preprocess] returns ok
Tue Aug 17 15:12:04 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:04 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP packet type response id 4 length 6
Tue Aug 17 15:12:04 2010 : Info: [eap] Continuing tunnel setup.
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns ok
Tue Aug 17 15:12:04 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:04 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:04 2010 : Info: [eap] Request found, released from the list
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP/peap
Tue Aug 17 15:12:04 2010 : Info: [eap] processing type peap
Tue Aug 17 15:12:04 2010 : Info: [peap] processing EAP-TLS
Tue Aug 17 15:12:04 2010 : Info: [peap] Received TLS ACK
Tue Aug 17 15:12:04 2010 : Info: [peap] ACK handshake fragment handler
Tue Aug 17 15:12:04 2010 : Info: [peap] eaptls_verify returned 1
Tue Aug 17 15:12:04 2010 : Info: [peap] eaptls_process returned 13
Tue Aug 17 15:12:04 2010 : Info: [peap] EAPTLS_HANDLED
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns handled
Sending Access-Challenge of id 15 to 10.10.100.5 port 1645
        EAP-Message = 0x010503fc19403359e7c7e93966521e088f67c70004ce308204ca308203b2a003020102020900e48713f69c7e235a300d06092a864886f70d010105050030819e310b3009060355040613025553310b3009060355040813024341310d300b060355040713044d4e574431263024060355040a131d4d6f756c746f6e204e696775656c2057617465722044697374726963743126302406092a864886f70d01090116174d6f756c746f6e537570706f7274406d6e77642e636f6d312330210603550403131a4d4e574420436572746966696361746520417574686f72697479301e170d3130303630343135343234365a170d313130363034313534323436
        EAP-Message = 0x5a30819e310b3009060355040613025553310b3009060355040813024341310d300b060355040713044d4e574431263024060355040a131d4d6f756c746f6e204e696775656c2057617465722044697374726963743126302406092a864886f70d01090116174d6f756c746f6e537570706f7274406d6e77642e636f6d312330210603550403131a4d4e574420436572746966696361746520417574686f7269747930820122300d06092a864886f70d01010105000382010f003082010a0282010100cc94f72b29fb5b1a44dd9ef8e556c4e24215de831861e56254ef737167ae76bcaaa5121db727117de6a14f3e80522055eb819b7052e66cc23a49
        EAP-Message = 0x965874abe7eefa99ee585692bf044365d1a95d59186c602f725a7ee036a1f52b812a6c3de76bd0cfe768c88ad0de299f49e9717516b4825445531ad36993482b84fe722cee11ed6d575ac51043ac1445bba6a0e90087890e2d486f8c7ed2a3464242fdad98740981df962092bd97d65f0f90750ccac2cda879c33537760e686aa91f1f46d7f49c47c2b75ae75772878e6c62b0b300650da434fac1514b5fa65742230c234e54c8a9805c05bbf52962370bfd27bbf28190f63fd08609b9f8bba08e7ff4aad0a10203010001a382010730820103301d0603551d0e0416041437ecc945ff19342e6a11660fb873758d2928cab23081d30603551d230481cb
        EAP-Message = 0x3081c8801437ecc945ff19342e6a11660fb873758d2928cab2a181a4a481a130819e310b3009060355040613025553310b3009060355040813024341310d300b060355040713044d4e574431263024060355040a131d4d6f756c746f6e204e696775656c2057617465722044697374726963743126302406092a864886f70d01090116174d6f756c746f6e537570706f7274406d6e77642e636f6d312330210603550403131a4d4e574420436572746966696361746520417574686f72697479820900e48713f69c7e235a300c0603551d13040530030101ff300d06092a864886f70d01010505000382010100478f546af2e0508923a7a6e1659f1e6a
        EAP-Message = 0xc29a237a5f310426
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd4b1f85ad6b4e16d5a9aa79773704d28
Tue Aug 17 15:12:04 2010 : Info: Finished request 2.
Tue Aug 17 15:12:04 2010 : Debug: Going to the next request
Tue Aug 17 15:12:04 2010 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.10.100.5 port 1645, id=16, length=146
        User-Name = "nking"
        Framed-MTU = 1400
        Called-Station-Id = "0021.a0f9.5121"
        Calling-Station-Id = "0013.0245.ab2a"
        Service-Type = Login-User
        Message-Authenticator = 0x6e9c3b0b1952fa3a567c56537f2fa7a6
        EAP-Message = 0x020500061900
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 611
        NAS-Port-Id = "611"
        State = 0xd4b1f85ad6b4e16d5a9aa79773704d28
        NAS-IP-Address = 10.10.100.5
        NAS-Identifier = "OPSap1"
Tue Aug 17 15:12:04 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:04 2010 : Info: ++[preprocess] returns ok
Tue Aug 17 15:12:04 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:04 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP packet type response id 5 length 6
Tue Aug 17 15:12:04 2010 : Info: [eap] Continuing tunnel setup.
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns ok
Tue Aug 17 15:12:04 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:04 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:04 2010 : Info: [eap] Request found, released from the list
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP/peap
Tue Aug 17 15:12:04 2010 : Info: [eap] processing type peap
Tue Aug 17 15:12:04 2010 : Info: [peap] processing EAP-TLS
Tue Aug 17 15:12:04 2010 : Info: [peap] Received TLS ACK
Tue Aug 17 15:12:04 2010 : Info: [peap] ACK handshake fragment handler
Tue Aug 17 15:12:04 2010 : Info: [peap] eaptls_verify returned 1
Tue Aug 17 15:12:04 2010 : Info: [peap] eaptls_process returned 13
Tue Aug 17 15:12:04 2010 : Info: [peap] EAPTLS_HANDLED
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns handled
Sending Access-Challenge of id 16 to 10.10.100.5 port 1645
        EAP-Message = 0x010600f719003d972368e5f5dbeb301b5f00e8ad98a9ad3fe9441b7d48a511e40f1786e65093dc44994a859333fe95a6df566546f3e0a3060238628785e2483d2ae8c1c82683b9bf540b6b7d7904fe01a1962e59e03ef9dc82692b5265fa617b56cd188f57ae82c2ce570338400dc60dbadf2ef9e7f4fd7da752c1e64b933a3d9af4b7ce7ed2b24dd9c3cab55087afafa32c0bd9d2ed051ca75f8cf78caa11c3007e2d58902338342d3008018957e02d7242628474aa7643b14c0f52d4905dd182486d04443fb9ddeb0cc99326cc887ec72aea9f5ebbd81760b705d99a75ad70b4e1b45e3dbbb5e01b9c80ae375016030100040e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd4b1f85ad7b7e16d5a9aa79773704d28
Tue Aug 17 15:12:04 2010 : Info: Finished request 3.
Tue Aug 17 15:12:04 2010 : Debug: Going to the next request
Tue Aug 17 15:12:04 2010 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.10.100.5 port 1645, id=17, length=462
        User-Name = "nking"
        Framed-MTU = 1400
        Called-Station-Id = "0021.a0f9.5121"
        Calling-Station-Id = "0013.0245.ab2a"
        Service-Type = Login-User
        Message-Authenticator = 0xfc7ef79d845963800893831ea2a54c55
        EAP-Message = 0x0206014019800000013616030101061000010201002b601b76e1554b08fe3f47f27cf141a7fa35f8fa074434c13b730ececc6c4186d21f37edc0c33beaa61ec11032aefac8874a11aafe7f24ce7ab1642605f93dee07635c4d56506d57be00dc3d4ff457ffb43cf50f4425b2258d24f27c7f7d4390a1f138797171e38bb9379067226b7c49e721b948902c10b264184fd5c9389bb96f1f8109e51cb2d3bb12e1b0f23317ddc245aa52a56f24aa72634c6b7d1a1b0efac2ebb6fe4dc591f04f46a7ca3be24e4e8e8c7499ec40d7fb32c6c05976e1b72b1f7f00740ccccd384e789e4b6e8857419713cc926d992d3c592ec090901c2cd1a6c008949e0004
        EAP-Message = 0x7526a8ab3675bd5841aa7cfc4e6d90792c98a6e7b6600d7f1403010001011603010020b4e9dee3f0e1fb9e338cf058d02f3fba6a8762dcf906aa93dd98281bc8f5d5b6
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 611
        NAS-Port-Id = "611"
        State = 0xd4b1f85ad7b7e16d5a9aa79773704d28
        NAS-IP-Address = 10.10.100.5
        NAS-Identifier = "OPSap1"
Tue Aug 17 15:12:04 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:04 2010 : Info: ++[preprocess] returns ok
Tue Aug 17 15:12:04 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:04 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP packet type response id 6 length 253
Tue Aug 17 15:12:04 2010 : Info: [eap] Continuing tunnel setup.
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns ok
Tue Aug 17 15:12:04 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:04 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:04 2010 : Info: [eap] Request found, released from the list
Tue Aug 17 15:12:04 2010 : Info: [eap] EAP/peap
Tue Aug 17 15:12:04 2010 : Info: [eap] processing type peap
Tue Aug 17 15:12:04 2010 : Info: [peap] processing EAP-TLS
Tue Aug 17 15:12:04 2010 : Debug:   TLS Length 310
Tue Aug 17 15:12:04 2010 : Info: [peap] Length Included
Tue Aug 17 15:12:04 2010 : Info: [peap] eaptls_verify returned 11
Tue Aug 17 15:12:04 2010 : Info: [peap] <<< TLS 1.0 Handshake [length 0106], ClientKeyExchange
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 read client key exchange A
Tue Aug 17 15:12:04 2010 : Info: [peap] <<< TLS 1.0 ChangeCipherSpec [length 0001]
Tue Aug 17 15:12:04 2010 : Info: [peap] <<< TLS 1.0 Handshake [length 0010], Finished
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 read finished A
Tue Aug 17 15:12:04 2010 : Info: [peap] >>> TLS 1.0 ChangeCipherSpec [length 0001]
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 write change cipher spec A
Tue Aug 17 15:12:04 2010 : Info: [peap] >>> TLS 1.0 Handshake [length 0010], Finished
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 write finished A
Tue Aug 17 15:12:04 2010 : Info: [peap]     TLS_accept: SSLv3 flush data
Tue Aug 17 15:12:04 2010 : Info: [peap]     (other): SSL negotiation finished successfully
Tue Aug 17 15:12:04 2010 : Debug: SSL Connection Established
Tue Aug 17 15:12:04 2010 : Info: [peap] eaptls_process returned 13
Tue Aug 17 15:12:04 2010 : Info: [peap] EAPTLS_HANDLED
Tue Aug 17 15:12:04 2010 : Info: ++[eap] returns handled
Sending Access-Challenge of id 17 to 10.10.100.5 port 1645
        EAP-Message = 0x0107003119001403010001011603010020861d53184f9ce1883ef174b2e70a103641a50648624727d3a113b6484c373adf
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd4b1f85ad0b6e16d5a9aa79773704d28
Tue Aug 17 15:12:04 2010 : Info: Finished request 4.
Tue Aug 17 15:12:04 2010 : Debug: Going to the next request
Tue Aug 17 15:12:04 2010 : Debug: Waking up in 4.9 seconds.
Tue Aug 17 15:12:09 2010 : Info: Cleaning up request 0 ID 13 with timestamp +77
Tue Aug 17 15:12:09 2010 : Info: Cleaning up request 1 ID 14 with timestamp +77
Tue Aug 17 15:12:09 2010 : Info: Cleaning up request 2 ID 15 with timestamp +77
Tue Aug 17 15:12:09 2010 : Info: Cleaning up request 3 ID 16 with timestamp +77
Tue Aug 17 15:12:09 2010 : Info: Cleaning up request 4 ID 17 with timestamp +77
Tue Aug 17 15:12:09 2010 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 10.10.100.5 port 1645, id=18, length=146
        User-Name = "nking"
        Framed-MTU = 1400
        Called-Station-Id = "0021.a0f9.5121"
        Calling-Station-Id = "0013.0245.ab2a"
        Service-Type = Login-User
        Message-Authenticator = 0x93c1bf250607712c9abf3e104848e789
        EAP-Message = 0x020700061900
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 611
        NAS-Port-Id = "611"
        State = 0xd4b1f85ad0b6e16d5a9aa79773704d28
        NAS-IP-Address = 10.10.100.5
        NAS-Identifier = "OPSap1"
Tue Aug 17 15:12:09 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:09 2010 : Info: ++[preprocess] returns ok
Tue Aug 17 15:12:09 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:09 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP packet type response id 7 length 6
Tue Aug 17 15:12:09 2010 : Info: [eap] Continuing tunnel setup.
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns ok
Tue Aug 17 15:12:09 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:09 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:09 2010 : Info: [eap] Request found, released from the list
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP/peap
Tue Aug 17 15:12:09 2010 : Info: [eap] processing type peap
Tue Aug 17 15:12:09 2010 : Info: [peap] processing EAP-TLS
Tue Aug 17 15:12:09 2010 : Info: [peap] Received TLS ACK
Tue Aug 17 15:12:09 2010 : Info: [peap] ACK handshake is finished
Tue Aug 17 15:12:09 2010 : Info: [peap] eaptls_verify returned 3
Tue Aug 17 15:12:09 2010 : Info: [peap] eaptls_process returned 3
Tue Aug 17 15:12:09 2010 : Info: [peap] EAPTLS_SUCCESS
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns handled
Sending Access-Challenge of id 18 to 10.10.100.5 port 1645
        EAP-Message = 0x0108002019001703010015b3bc0d3fb0195069dffc2c9a7439089a995c718b1a
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd4b1f85ad1b9e16d5a9aa79773704d28
Tue Aug 17 15:12:09 2010 : Info: Finished request 5.
Tue Aug 17 15:12:09 2010 : Debug: Going to the next request
Tue Aug 17 15:12:09 2010 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.10.100.5 port 1645, id=19, length=173
        User-Name = "nking"
        Framed-MTU = 1400
        Called-Station-Id = "0021.a0f9.5121"
        Calling-Station-Id = "0013.0245.ab2a"
        Service-Type = Login-User
        Message-Authenticator = 0x35d88ee4a4b9dffa130bf697a63d1b35
        EAP-Message = 0x020800211900170301001696ef2665052cc502c10aa70c0722b82afb250f36ece6
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 611
        NAS-Port-Id = "611"
        State = 0xd4b1f85ad1b9e16d5a9aa79773704d28
        NAS-IP-Address = 10.10.100.5
        NAS-Identifier = "OPSap1"
Tue Aug 17 15:12:09 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:09 2010 : Info: ++[preprocess] returns ok
Tue Aug 17 15:12:09 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:09 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP packet type response id 8 length 33
Tue Aug 17 15:12:09 2010 : Info: [eap] Continuing tunnel setup.
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns ok
Tue Aug 17 15:12:09 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:09 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:09 2010 : Info: [eap] Request found, released from the list
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP/peap
Tue Aug 17 15:12:09 2010 : Info: [eap] processing type peap
Tue Aug 17 15:12:09 2010 : Info: [peap] processing EAP-TLS
Tue Aug 17 15:12:09 2010 : Info: [peap] eaptls_verify returned 7
Tue Aug 17 15:12:09 2010 : Info: [peap] Done initial handshake
Tue Aug 17 15:12:09 2010 : Info: [peap] eaptls_process returned 7
Tue Aug 17 15:12:09 2010 : Info: [peap] EAPTLS_OK
Tue Aug 17 15:12:09 2010 : Info: [peap] Session established.  Decoding tunneled attributes.
  PEAP tunnel data in 0000: 01 6e 6b 69 6e 67
Tue Aug 17 15:12:09 2010 : Info: [peap] Identity - nking
Tue Aug 17 15:12:09 2010 : Info: [peap] Got tunneled request
        EAP-Message = 0x0208000a016e6b696e67
server  {
Tue Aug 17 15:12:09 2010 : Debug:   PEAP: Got tunneled identity of nking
Tue Aug 17 15:12:09 2010 : Debug:   PEAP: Setting default EAP type for tunneled EAP session.
Tue Aug 17 15:12:09 2010 : Debug:   PEAP: Setting User-Name to nking
Sending tunneled request
        EAP-Message = 0x0208000a016e6b696e67
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "nking"
server inner-tunnel {
Tue Aug 17 15:12:09 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:09 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:09 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP packet type response id 8 length 10
Tue Aug 17 15:12:09 2010 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns updated
Tue Aug 17 15:12:09 2010 : Info: ++[files] returns noop
Tue Aug 17 15:12:09 2010 : Info: ++[expiration] returns noop
Tue Aug 17 15:12:09 2010 : Info: ++[logintime] returns noop
Tue Aug 17 15:12:09 2010 : Info: [pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Tue Aug 17 15:12:09 2010 : Info: ++[pap] returns noop
Tue Aug 17 15:12:09 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:09 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP Identity
Tue Aug 17 15:12:09 2010 : Info: [eap] processing type mschapv2
Tue Aug 17 15:12:09 2010 : Debug: rlm_eap_mschapv2: Issuing Challenge
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns handled
} # server inner-tunnel
Tue Aug 17 15:12:09 2010 : Info: [peap] Got tunneled reply code 11
        EAP-Message = 0x0109001f1a0109001a10e12162160781ff1fc5d10e83d370c8566e6b696e67
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x6be8aa436be1b0aa2a2b8389f4fa0825
Tue Aug 17 15:12:09 2010 : Info: [peap] Got tunneled reply RADIUS code 11
        EAP-Message = 0x0109001f1a0109001a10e12162160781ff1fc5d10e83d370c8566e6b696e67
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x6be8aa436be1b0aa2a2b8389f4fa0825
Tue Aug 17 15:12:09 2010 : Info: [peap] Got tunneled Access-Challenge
  PEAP tunnel data out 0000: 1a 01 09 00 1a 10 e1 21 62 16 07 81 ff 1f c5 d1
  PEAP tunnel data out 0010: 0e 83 d3 70 c8 56 6e 6b 69 6e 67
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns handled
Sending Access-Challenge of id 19 to 10.10.100.5 port 1645
        EAP-Message = 0x010900361900170301002bc85cae7b4414d9af379017b4fbd4ecde02d2053122ece5c810e8213997abb59421959ec069513a23aa5eb9
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd4b1f85ad2b8e16d5a9aa79773704d28
Tue Aug 17 15:12:09 2010 : Info: Finished request 6.
Tue Aug 17 15:12:09 2010 : Debug: Going to the next request
Tue Aug 17 15:12:09 2010 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.10.100.5 port 1645, id=20, length=227
        User-Name = "nking"
        Framed-MTU = 1400
        Called-Station-Id = "0021.a0f9.5121"
        Calling-Station-Id = "0013.0245.ab2a"
        Service-Type = Login-User
        Message-Authenticator = 0x2ea092077e352b727f145132f2416d4b
        EAP-Message = 0x020900571900170301004c7ee84ebf1c11b8371deab6dcaa359a198edf53d211d3556779b3e3b03d206e71835c9b60a7261cf169f8667494f0cb94b5932f1199ec0cfa76792dad817976ca1040c2c752d5d04130b9dbeb
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 611
        NAS-Port-Id = "611"
        State = 0xd4b1f85ad2b8e16d5a9aa79773704d28
        NAS-IP-Address = 10.10.100.5
        NAS-Identifier = "OPSap1"
Tue Aug 17 15:12:09 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:09 2010 : Info: ++[preprocess] returns ok
Tue Aug 17 15:12:09 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:09 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP packet type response id 9 length 87
Tue Aug 17 15:12:09 2010 : Info: [eap] Continuing tunnel setup.
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns ok
Tue Aug 17 15:12:09 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:09 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:09 2010 : Info: [eap] Request found, released from the list
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP/peap
Tue Aug 17 15:12:09 2010 : Info: [eap] processing type peap
Tue Aug 17 15:12:09 2010 : Info: [peap] processing EAP-TLS
Tue Aug 17 15:12:09 2010 : Info: [peap] eaptls_verify returned 7
Tue Aug 17 15:12:09 2010 : Info: [peap] Done initial handshake
Tue Aug 17 15:12:09 2010 : Info: [peap] eaptls_process returned 7
Tue Aug 17 15:12:09 2010 : Info: [peap] EAPTLS_OK
Tue Aug 17 15:12:09 2010 : Info: [peap] Session established.  Decoding tunneled attributes.
  PEAP tunnel data in 0000: 1a 02 09 00 3b 31 69 61 c6 e9 a3 0a aa 96 6b 68
  PEAP tunnel data in 0010: 80 eb d6 71 6e c6 00 00 00 00 00 00 00 00 80 99
  PEAP tunnel data in 0020: bf 39 46 d9 21 a0 b4 cf fd a8 9c c4 9b 3c e6 28
  PEAP tunnel data in 0030: fa 0b e6 2d 82 28 00 6e 6b 69 6e 67
Tue Aug 17 15:12:09 2010 : Info: [peap] EAP type mschapv2
Tue Aug 17 15:12:09 2010 : Info: [peap] Got tunneled request
        EAP-Message = 0x020900401a0209003b316961c6e9a30aaa966b6880ebd6716ec600000000000000008099bf3946d921a0b4cffda89cc49b3ce628fa0be62d8228006e6b696e67
server  {
Tue Aug 17 15:12:09 2010 : Debug:   PEAP: Setting User-Name to nking
Sending tunneled request
        EAP-Message = 0x020900401a0209003b316961c6e9a30aaa966b6880ebd6716ec600000000000000008099bf3946d921a0b4cffda89cc49b3ce628fa0be62d8228006e6b696e67
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "nking"
        State = 0x6be8aa436be1b0aa2a2b8389f4fa0825
server inner-tunnel {
Tue Aug 17 15:12:09 2010 : Info: +- entering group authorize {...}
Tue Aug 17 15:12:09 2010 : Info: ++[chap] returns noop
Tue Aug 17 15:12:09 2010 : Info: ++[mschap] returns noop
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP packet type response id 9 length 64
Tue Aug 17 15:12:09 2010 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns updated
Tue Aug 17 15:12:09 2010 : Info: ++[files] returns noop
Tue Aug 17 15:12:09 2010 : Info: ++[expiration] returns noop
Tue Aug 17 15:12:09 2010 : Info: ++[logintime] returns noop
Tue Aug 17 15:12:09 2010 : Info: [pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Tue Aug 17 15:12:09 2010 : Info: ++[pap] returns noop
Tue Aug 17 15:12:09 2010 : Info: Found Auth-Type = EAP
Tue Aug 17 15:12:09 2010 : Info: +- entering group authenticate {...}
Tue Aug 17 15:12:09 2010 : Info: [eap] Request found, released from the list
Tue Aug 17 15:12:09 2010 : Info: [eap] EAP/mschapv2
Tue Aug 17 15:12:09 2010 : Info: [eap] processing type mschapv2
Tue Aug 17 15:12:09 2010 : Info: [mschapv2] +- entering group MS-CHAP {...}
Tue Aug 17 15:12:09 2010 : Info: [mschap] Told to do MS-CHAPv2 for nking with NT-Password
Tue Aug 17 15:12:09 2010 : Info: [mschap]       expand: %{Stripped-User-Name} ->
Tue Aug 17 15:12:09 2010 : Info: [mschap]       ... expanding second conditional
Tue Aug 17 15:12:09 2010 : Info: [mschap] WARNING: Deprecated conditional expansion ":-".  See "man unlang" for details
Tue Aug 17 15:12:09 2010 : Info: [mschap]       expand: %{User-Name:-None} -> nking
Tue Aug 17 15:12:09 2010 : Info: [mschap]       expand: --username=%{%{Stripped-User-Name}:-%{User-Name:-None}} -> --username=nking
Tue Aug 17 15:12:09 2010 : Info: [mschap]  mschap2: e1
Tue Aug 17 15:12:09 2010 : Info: [mschap]       expand: --challenge=%{mschap:Challenge:-00} -> --challenge=2561c400f4a7ef1b
Tue Aug 17 15:12:09 2010 : Info: [mschap]       expand: --nt-response=%{mschap:NT-Response:-00} -> --nt-response=8099bf3946d921a0b4cffda89cc49b3ce628fa0be62d8228
[2010/08/17 15:12:09,  5] lib/debug.c:407(debug_dump_status)
  INFO: Current debug levels:
    all: True/10
    tdb: False/0
    printdrivers: False/0
    lanman: False/0
    smb: False/0
    rpc_parse: False/0
    rpc_srv: False/0
    rpc_cli: False/0
    passdb: False/0
    sam: False/0
    auth: False/0
    winbind: False/0
    vfs: False/0
    idmap: False/0
    quota: False/0
    acls: False/0
    locking: False/0
    msdfs: False/0
    dmapi: False/0
    registry: False/0
  doing parameter syslog = 0
  doing parameter log file = /var/opt/samba/log.%m
  doing parameter max log size = 1000
  doing parameter wins support = Yes
  doing parameter idmap uid = 15000-1500000
  doing parameter idmap gid = 15000-1500000
  doing parameter template shell = /bin/bash
  doing parameter winbind enum users = Yes
  doing parameter read only = No
  doing parameter guest ok = yes
[2010/08/17 15:12:09,  4] param/loadparm.c:9066(lp_load_ex)
  pm_process() returned Yes
[2010/08/17 15:12:09,  7] param/loadparm.c:9271(lp_servicenumber)
  lp_servicenumber: couldn't find homes
[2010/08/17 15:12:09, 10] param/loadparm.c:8279(set_server_role)
  set_server_role: role = ROLE_DOMAIN_MEMBER
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
[2010/08/17 15:12:09,  5] lib/charcnv.c:82(charset_name)
  Substituting charset 'ANSI_X3.4-1968' for LOCALE
Tue Aug 17 15:12:09 2010 : Debug: Exec-Program output: NT_KEY: B7C9D79D97D6C7C66C70EFDDAC880DFD
Tue Aug 17 15:12:09 2010 : Debug: Exec-Program-Wait: plaintext: NT_KEY: B7C9D79D97D6C7C66C70EFDDAC880DFD
Tue Aug 17 15:12:09 2010 : Debug: Exec-Program: returned: 0
Tue Aug 17 15:12:09 2010 : Info: ++[mschap] returns ok
Tue Aug 17 15:12:09 2010 : Debug: MSCHAP Success
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns handled
} # server inner-tunnel
Tue Aug 17 15:12:09 2010 : Info: [peap] Got tunneled reply code 11
        EAP-Message = 0x010a00331a0309002e533d32394141433844334430324139453442353945433641363738464243373343454437423546413234
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x6be8aa436ae2b0aa2a2b8389f4fa0825
Tue Aug 17 15:12:09 2010 : Info: [peap] Got tunneled reply RADIUS code 11
        EAP-Message = 0x010a00331a0309002e533d32394141433844334430324139453442353945433641363738464243373343454437423546413234
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x6be8aa436ae2b0aa2a2b8389f4fa0825
Tue Aug 17 15:12:09 2010 : Info: [peap] Got tunneled Access-Challenge
  PEAP tunnel data out 0000: 1a 03 09 00 2e 53 3d 32 39 41 41 43 38 44 33 44
  PEAP tunnel data out 0010: 30 32 41 39 45 34 42 35 39 45 43 36 41 36 37 38
  PEAP tunnel data out 0020: 46 42 43 37 33 43 45 44 37 42 35 46 41 32 34
Tue Aug 17 15:12:09 2010 : Info: ++[eap] returns handled
Sending Access-Challenge of id 20 to 10.10.100.5 port 1645
        EAP-Message = 0x010a004a1900170301003ffb72f29ac4472eade653dc5bd4480126136e67dcfaf4d4668227f9980672562443486f5451f131439ae5552513e432f2d4749c7df853dc42d4a7045c2732b4
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd4b1f85ad3bbe16d5a9aa79773704d28
Tue Aug 17 15:12:09 2010 : Info: Finished request 7.
Tue Aug 17 15:12:09 2010 : Debug: Going to the next request
Tue Aug 17 15:12:09 2010 : Debug: Waking up in 4.9 seconds.

Flaky AP or borked Config? EAP-PEAP

Nolan King