ntlm_auth not working from within Freeradius with Domain in Username

19 Jan 2009

      Hi,

like to use freradius to authenticate wireless users against an existing
windows AD. My enviorment Cisco AP, Router and Switch. An Windows 2003
AD server. My Freeradius server is an ubuntu 80.04 LTS with freeradius
1.1.7 compiled with tls of course.

The relevant mschap configs looks like:
  mschap {
    use_mppe = no
    require_encryption = no
    require_strong = no
    with_ntdomain_hack = yes
    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}"
    }

So if i now try to connect with a Vista Client. It pops up with the 3
fields username/password/domain as usual. Now if i use username/password
it works fine and if i use user/pass/domain it does not.
As i may have multiple domains at the end i need that part working as well.

I guess smb.conf/krb5.cnf is right as i can fire up the same output i
see in the debug output from freeradius.
Eg.

su freerad -s /bin/sh -c 'ntlm_auth --username=TEST\\ingo
--request-nt-key --challenge=25226c1fad0393e9
--nt-response=025af5ee1b7742613e7c12f0dfd01ceb71817adf605db585'
NT_KEY: AE33A32DCA8C9821844F740D5B3F4D6C

It comes back with the expected key. The keys are from one of the
requests as seen in the Freeradius debug msg.

Fri Jan 16 16:14:05 2009 : Debug:   rlm_mschap: Told to do MS-CHAPv2 for
ingo with NT-Password
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat:  '--username=TEST\\ingo'
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: Running registered xlat
function
of module mschap for string 'Challenge'
Fri Jan 16 16:14:05 2009 : Debug:  mschap2: 9c
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat:
'--challenge=25226c1fad0393e9'
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: Running registered xlat
function
of module mschap for string 'NT-Response'
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat:
'--nt-response=025af5ee1b7742613e7c12f0dfd01ceb71817adf605db585'
Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds...
Fri Jan 16 16:14:05 2009 : Debug: Threads: total/active/spare threads =
5/1/4
Fri Jan 16 16:14:05 2009 : Debug: Exec-Program output: Logon failure
(0xc000006d)
Fri Jan 16 16:14:05 2009 : Debug: Exec-Program-Wait: plaintext: Logon
failure (0xc000006d)
Fri Jan 16 16:14:05 2009 : Debug: Exec-Program: returned: 1

There is one difference ...... when i replace ntlm_auth with an own
little script to just print the argv in file i do get:

--request-nt-key --username=TEST\ingo --challenge=20ae2cce3a27e116
--nt-response=b862a58e5bccd288c367af67368ced711ded1e132159fc5a

There is just one little difference compare to what i do on the bash
itself. Thats the // vs / in the username. I guess Freeradius does send
one / so TEST/ingo butif i woudl do it on the shell bash would strip it.
so i need //.

Apart from that i run out of ideas why auth fails as soon as i send a
Domain name. Just username7password works as the radius servers samaba
is in the Test Domain.

Anyone an idea on how to furter debug ?

I alreay tryed adding some prints infront of the relevant execve but
they kill the logic of feeding the ntlm_response back to the parent.
I guess it will look similar to what i see in the Script when i print
the ARGV but not sure.

Regards
	Holger

Complete Debug msg:
Fri Jan 16 16:12:56 2009 : Info: Starting - reading configuration files ...
Fri Jan 16 16:12:56 2009 : Debug: reread_config:  reading radiusd.conf
Fri Jan 16 16:12:56 2009 : Debug: Config:   including file:
/etc/freeradius/proxy.conf
Fri Jan 16 16:12:56 2009 : Debug: Config:   including file:
/etc/freeradius/clients.conf
Fri Jan 16 16:12:56 2009 : Debug: Config:   including file:
/etc/freeradius/snmp.conf
Fri Jan 16 16:12:56 2009 : Debug: Config:   including file:
/etc/freeradius/eap.conf
Fri Jan 16 16:12:56 2009 : Debug:  main: prefix = "/usr"
Fri Jan 16 16:12:56 2009 : Debug:  main: localstatedir = "/var"
Fri Jan 16 16:12:56 2009 : Debug:  main: logdir = "/var/log/freeradius"
Fri Jan 16 16:12:56 2009 : Debug:  main: libdir = "/usr/lib/freeradius"
Fri Jan 16 16:12:56 2009 : Debug:  main: radacctdir =
"/var/log/freeradius/radacct"
Fri Jan 16 16:12:56 2009 : Debug:  main: hostname_lookups = no
Fri Jan 16 16:12:56 2009 : Debug:  main: snmp = no
Fri Jan 16 16:12:56 2009 : Debug:  main: max_request_time = 30
Fri Jan 16 16:12:56 2009 : Debug:  main: cleanup_delay = 5
Fri Jan 16 16:12:56 2009 : Debug:  main: max_requests = 1024
Fri Jan 16 16:12:56 2009 : Debug:  main: delete_blocked_requests = 0
Fri Jan 16 16:12:56 2009 : Debug:  main: port = 0
Fri Jan 16 16:12:56 2009 : Debug:  main: allow_core_dumps = no
Fri Jan 16 16:12:56 2009 : Debug:  main: log_stripped_names = no
Fri Jan 16 16:12:56 2009 : Debug:  main: log_file =
"/var/log/freeradius/radius.log"
Fri Jan 16 16:12:56 2009 : Debug:  main: log_auth = yes
Fri Jan 16 16:12:56 2009 : Debug:  main: log_auth_badpass = yes
Fri Jan 16 16:12:56 2009 : Debug:  main: log_auth_goodpass = yes
Fri Jan 16 16:12:56 2009 : Debug:  main: pidfile =
"/var/run/freeradius/freeradius.pid"
Fri Jan 16 16:12:56 2009 : Debug:  main: user = "freerad"
Fri Jan 16 16:12:56 2009 : Debug:  main: group = "freerad"
Fri Jan 16 16:12:56 2009 : Debug:  main: usercollide = no
Fri Jan 16 16:12:56 2009 : Debug:  main: lower_user = "no"
Fri Jan 16 16:12:56 2009 : Debug:  main: lower_pass = "no"
Fri Jan 16 16:12:56 2009 : Debug:  main: nospace_user = "no"
Fri Jan 16 16:12:56 2009 : Debug:  main: nospace_pass = "no"
Fri Jan 16 16:12:56 2009 : Debug:  main: checkrad = "/usr/sbin/checkrad"
Fri Jan 16 16:12:56 2009 : Debug:  main: proxy_requests = yes
Fri Jan 16 16:12:56 2009 : Debug:  proxy: retry_delay = 5
Fri Jan 16 16:12:56 2009 : Debug:  proxy: retry_count = 3
Fri Jan 16 16:12:56 2009 : Debug:  proxy: synchronous = no
Fri Jan 16 16:12:56 2009 : Debug:  proxy: default_fallback = yes
Fri Jan 16 16:12:56 2009 : Debug:  proxy: dead_time = 120
Fri Jan 16 16:12:56 2009 : Debug:  proxy: post_proxy_authorize = no
Fri Jan 16 16:12:56 2009 : Debug:  proxy: wake_all_if_all_dead = no
Fri Jan 16 16:12:56 2009 : Debug:  security: max_attributes = 200
Fri Jan 16 16:12:56 2009 : Debug:  security: reject_delay = 1
Fri Jan 16 16:12:56 2009 : Debug:  security: status_server = no
Fri Jan 16 16:12:56 2009 : Debug:  main: debug_level = 0
Fri Jan 16 16:12:56 2009 : Debug: read_config_files:  reading dictionary
Fri Jan 16 16:12:56 2009 : Debug: read_config_files:  reading naslist
Fri Jan 16 16:12:56 2009 : Info: Using deprecated naslist file.  Support
for this will go away soon.
Fri Jan 16 16:12:56 2009 : Debug: read_config_files:  reading clients
Fri Jan 16 16:12:56 2009 : Debug: read_config_files:  reading realms
Fri Jan 16 16:12:56 2009 : Debug: radiusd:  entering modules setup
Fri Jan 16 16:12:56 2009 : Debug: Module: Library search path is
/usr/lib/freeradius
Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded exec
Fri Jan 16 16:12:56 2009 : Debug:  exec: wait = yes
Fri Jan 16 16:12:56 2009 : Debug:  exec: program = "(null)"
Fri Jan 16 16:12:56 2009 : Debug:  exec: input_pairs = "request"
Fri Jan 16 16:12:56 2009 : Debug:  exec: output_pairs = "(null)"
Fri Jan 16 16:12:56 2009 : Debug:  exec: packet_type = "(null)"
Fri Jan 16 16:12:56 2009 : Info: rlm_exec: Wait=yes but no output
defined. Did you mean output=none?
Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated exec (exec)
Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded expr
Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated expr (expr)
Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded PAP
Fri Jan 16 16:12:56 2009 : Debug:  pap: encryption_scheme = "crypt"
Fri Jan 16 16:12:56 2009 : Debug:  pap: auto_header = yes
Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated pap (pap)
Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded CHAP
Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated chap (chap)
Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded MS-CHAP
Fri Jan 16 16:12:56 2009 : Debug:  mschap: use_mppe = no
Fri Jan 16 16:12:56 2009 : Debug:  mschap: require_encryption = yes
Fri Jan 16 16:12:56 2009 : Debug:  mschap: require_strong = yes
Fri Jan 16 16:12:56 2009 : Debug:  mschap: with_ntdomain_hack = yes
Fri Jan 16 16:12:56 2009 : Debug:  mschap: passwd = "(null)"
Fri Jan 16 16:12:56 2009 : Debug:  mschap: 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}"
Fri Jan 16 16:12:56 2009 : Debug: Module: Instantiated mschap (mschap)
Fri Jan 16 16:12:56 2009 : Debug: Module: Loaded eap
Fri Jan 16 16:12:56 2009 : Debug:  eap: default_eap_type = "peap"
Fri Jan 16 16:12:56 2009 : Debug:  eap: timer_expire = 60
Fri Jan 16 16:12:56 2009 : Debug:  eap: ignore_unknown_eap_types = no
Fri Jan 16 16:12:56 2009 : Debug:  eap: cisco_accounting_username_bug = no
Fri Jan 16 16:12:56 2009 : Debug: rlm_eap: Loaded and initialized type md5
Fri Jan 16 16:12:56 2009 : Debug: rlm_eap: Loaded and initialized type leap
Fri Jan 16 16:12:56 2009 : Debug:  gtc: challenge = "Password: "
Fri Jan 16 16:12:56 2009 : Debug:  gtc: auth_type = "PAP"
Fri Jan 16 16:12:56 2009 : Debug: rlm_eap: Loaded and initialized type gtc
Fri Jan 16 16:12:56 2009 : Debug:  tls: rsa_key_exchange = no
Fri Jan 16 16:12:56 2009 : Debug:  tls: dh_key_exchange = yes
Fri Jan 16 16:12:56 2009 : Debug:  tls: rsa_key_length = 512
Fri Jan 16 16:12:56 2009 : Debug:  tls: dh_key_length = 512
Fri Jan 16 16:12:56 2009 : Debug:  tls: verify_depth = 0
Fri Jan 16 16:12:56 2009 : Debug:  tls: CA_path = "(null)"
Fri Jan 16 16:12:56 2009 : Debug:  tls: pem_file_type = yes
Fri Jan 16 16:12:56 2009 : Debug:  tls: private_key_file =
"/etc/freeradius/certs/cert-srv.pem"
Fri Jan 16 16:12:56 2009 : Debug:  tls: certificate_file =
"/etc/freeradius/certs/cert-srv.pem"
Fri Jan 16 16:12:56 2009 : Debug:  tls: CA_file =
"/etc/freeradius/certs/demoCA/cacert.pem"
Fri Jan 16 16:12:56 2009 : Debug:  tls: private_key_password = "whatever"
Fri Jan 16 16:12:56 2009 : Debug:  tls: dh_file = "/etc/freeradius/certs/dh"
Fri Jan 16 16:12:56 2009 : Debug:  tls: random_file = "/dev/urandom"
Fri Jan 16 16:12:56 2009 : Debug:  tls: fragment_size = 1024
Fri Jan 16 16:12:56 2009 : Debug:  tls: include_length = yes
Fri Jan 16 16:12:56 2009 : Debug:  tls: check_crl = no
Fri Jan 16 16:12:56 2009 : Debug:  tls: check_cert_cn = "(null)"
Fri Jan 16 16:12:56 2009 : Debug:  tls: cipher_list = "(null)"
Fri Jan 16 16:12:56 2009 : Debug:  tls: check_cert_issuer = "(null)"
Fri Jan 16 16:12:56 2009 : Info: rlm_eap_tls: Loading the certificate
file as a chain
Fri Jan 16 16:12:57 2009 : Info: WARNING: rlm_eap_tls: Unable to set DH
parameters.  DH cipher suites may not work!
Fri Jan 16 16:12:57 2009 : Debug: WARNING: Fix this by running the
OpenSSL command listed in eap.conf
Fri Jan 16 16:12:57 2009 : Debug: rlm_eap: Loaded and initialized type tls
Fri Jan 16 16:12:57 2009 : Debug:  peap: default_eap_type = "mschapv2"
Fri Jan 16 16:12:57 2009 : Debug:  peap: copy_request_to_tunnel = no
Fri Jan 16 16:12:57 2009 : Debug:  peap: use_tunneled_reply = no
Fri Jan 16 16:12:57 2009 : Debug:  peap: proxy_tunneled_request_as_eap = yes
Fri Jan 16 16:12:57 2009 : Debug: rlm_eap: Loaded and initialized type peap
Fri Jan 16 16:12:57 2009 : Debug:  mschapv2: with_ntdomain_hack = no
Fri Jan 16 16:12:57 2009 : Debug: rlm_eap: Loaded and initialized type
mschapv2
Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated eap (eap)
Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded preprocess
Fri Jan 16 16:12:57 2009 : Debug:  preprocess: huntgroups =
"/etc/freeradius/huntgroups"
Fri Jan 16 16:12:57 2009 : Debug:  preprocess: hints =
"/etc/freeradius/hints"
Fri Jan 16 16:12:57 2009 : Debug:  preprocess: with_ascend_hack = no
Fri Jan 16 16:12:57 2009 : Debug:  preprocess: ascend_channels_per_line = 23
Fri Jan 16 16:12:57 2009 : Debug:  preprocess: with_ntdomain_hack = no
Fri Jan 16 16:12:57 2009 : Debug:  preprocess:
with_specialix_jetstream_hack = no
Fri Jan 16 16:12:57 2009 : Debug:  preprocess: with_cisco_vsa_hack = no
Fri Jan 16 16:12:57 2009 : Debug:  preprocess: with_alvarion_vsa_hack = no
Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated preprocess
(preprocess)
Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded files
Fri Jan 16 16:12:57 2009 : Debug:  files: usersfile =
"/etc/freeradius/users"
Fri Jan 16 16:12:57 2009 : Debug:  files: acctusersfile =
"/etc/freeradius/acct_users"
Fri Jan 16 16:12:57 2009 : Debug:  files: preproxy_usersfile =
"/etc/freeradius/preproxy_users"
Fri Jan 16 16:12:57 2009 : Debug:  files: compat = "no"
Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated files (files)
Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded Acct-Unique-Session-Id
Fri Jan 16 16:12:57 2009 : Debug:  acct_unique: key = "User-Name,
Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated acct_unique
(acct_unique)
Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded realm
Fri Jan 16 16:12:57 2009 : Debug:  realm: format = "suffix"
Fri Jan 16 16:12:57 2009 : Debug:  realm: delimiter = "@"
Fri Jan 16 16:12:57 2009 : Debug:  realm: ignore_default = no
Fri Jan 16 16:12:57 2009 : Debug:  realm: ignore_null = no
Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated realm (suffix)
Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded detail
Fri Jan 16 16:12:57 2009 : Debug:  detail: detailfile =
"/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Fri Jan 16 16:12:57 2009 : Debug:  detail: detailperm = 384
Fri Jan 16 16:12:57 2009 : Debug:  detail: dirperm = 493
Fri Jan 16 16:12:57 2009 : Debug:  detail: locking = no
Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated detail (detail)
Fri Jan 16 16:12:57 2009 : Debug: Module: Loaded radutmp
Fri Jan 16 16:12:57 2009 : Debug:  radutmp: filename =
"/var/log/freeradius/radutmp"
Fri Jan 16 16:12:57 2009 : Debug:  radutmp: username = "%{User-Name}"
Fri Jan 16 16:12:57 2009 : Debug:  radutmp: case_sensitive = yes
Fri Jan 16 16:12:57 2009 : Debug:  radutmp: check_with_nas = yes
Fri Jan 16 16:12:57 2009 : Debug:  radutmp: perm = 384
Fri Jan 16 16:12:57 2009 : Debug:  radutmp: callerid = yes
Fri Jan 16 16:12:57 2009 : Debug: Module: Instantiated radutmp (radutmp)
Fri Jan 16 16:12:57 2009 : Debug: Initializing the thread pool...
Fri Jan 16 16:12:57 2009 : Debug:  thread: start_servers = 5
Fri Jan 16 16:12:57 2009 : Debug:  thread: max_servers = 32
Fri Jan 16 16:12:57 2009 : Debug:  thread: min_spare_servers = 3
Fri Jan 16 16:12:57 2009 : Debug:  thread: max_spare_servers = 10
Fri Jan 16 16:12:57 2009 : Debug:  thread: max_requests_per_server = 0
Fri Jan 16 16:12:57 2009 : Debug:  thread: cleanup_delay = 5
Fri Jan 16 16:12:57 2009 : Debug: Thread 1 waiting to be assigned a request
Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 1. Total
threads in pool: 1
Fri Jan 16 16:12:57 2009 : Debug: Thread 2 waiting to be assigned a request
Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 2. Total
threads in pool: 2
Fri Jan 16 16:12:57 2009 : Debug: Thread 3 waiting to be assigned a request
Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 3. Total
threads in pool: 3
Fri Jan 16 16:12:57 2009 : Debug: Thread 4 waiting to be assigned a request
Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 4. Total
threads in pool: 4
Fri Jan 16 16:12:57 2009 : Debug: Thread 5 waiting to be assigned a request
Fri Jan 16 16:12:57 2009 : Debug: Thread spawned new child 5. Total
threads in pool: 5
Fri Jan 16 16:12:57 2009 : Debug: Thread pool initialized
Fri Jan 16 16:12:57 2009 : Debug: Listening on authentication *:1812
Fri Jan 16 16:12:57 2009 : Debug: Listening on accounting *:1813
Fri Jan 16 16:12:57 2009 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 192.168.0.10:1645, id=119,
length=131
Fri Jan 16 16:14:05 2009 : Debug: --- Walking the entire request list ---
Fri Jan 16 16:14:05 2009 : Debug: Thread 1 got semaphore
Fri Jan 16 16:14:05 2009 : Debug: Thread 1 handling request 0, (1
handled so far)
	User-Name = "TEST\\ingo"
	Framed-MTU = 1400
	Called-Station-Id = "0014.1bb5.abe0"
	Calling-Station-Id = "001f.3ba6.c02f"
	Service-Type = Login-User
	Message-Authenticator = 0xb84d1174c3d3c8b898c5fd8d95f4e061
	EAP-Message = 0x0202000e01544553545c696e676f
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 447
	NAS-IP-Address = 192.168.0.10
	NAS-Identifier = "ap"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
2 length 14
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 0
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 0
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 0
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP Identity
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type tls
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: Initiate
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: Start returned 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 0
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns handled for request 0
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns handled) for request 0
Sending Access-Challenge of id 119 to 192.168.0.10 port 1645
	EAP-Message = 0x010300061920
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x3622b9d5d04e6552a9c7b3220f54bf19
Fri Jan 16 16:14:05 2009 : Debug: Finished request 0
Fri Jan 16 16:14:05 2009 : Debug: Going to the next request
Fri Jan 16 16:14:05 2009 : Debug: Thread 1 waiting to be assigned a request
Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds...
Fri Jan 16 16:14:05 2009 : Debug: Threads: total/active/spare threads =
5/0/5
rad_recv: Access-Request packet from host 192.168.0.10:1645, id=120,
length=255
Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds...
Fri Jan 16 16:14:05 2009 : Debug: Thread 2 got semaphore
Fri Jan 16 16:14:05 2009 : Debug: Thread 2 handling request 1, (1
handled so far)
	User-Name = "TEST\\ingo"
	Framed-MTU = 1400
	Called-Station-Id = "0014.1bb5.abe0"
	Calling-Station-Id = "001f.3ba6.c02f"
	Service-Type = Login-User
	Message-Authenticator = 0x81e0b531d499a03fad2cabbe0136dbcb
	EAP-Message =
0x0203007819800000006e16030100690100006503014970a43cd3c00043f4020f78dab64dd6fd1109b18b42781457d7ea678061b4dd000018002f00350005000ac009c00ac013c0140032003800130004010000240000000e000c000009746573745c696e676f000a00080006001700180019000b00020100
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 447
	State = 0x3622b9d5d04e6552a9c7b3220f54bf19
	NAS-IP-Address = 192.168.0.10
	NAS-Identifier = "ap"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
3 length 120
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 1
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 1
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 1
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Request found, released
from the list
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP/peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Authenticate
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: processing TLS
Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls:  Length Included
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_verify returned 11
Fri Jan 16 16:14:05 2009 : Debug:     (other): before/accept initialization
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: before/accept
initialization
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake
[length 0069], ClientHello
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 read client hello A
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake
[length 004a], ServerHello
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 write server
hello A
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake
[length 0694], Certificate
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 write certificate A
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake
[length 0004], ServerHelloDone
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 write server done A
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 flush data
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: Need to read more
data: SSLv3 read client certificate A
Fri Jan 16 16:14:05 2009 : Debug: In SSL Handshake Phase
Fri Jan 16 16:14:05 2009 : Debug: In SSL Accept mode
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_process returned 13
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: EAPTLS_HANDLED
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 1
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns handled for request 1
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns handled) for request 1
Sending Access-Challenge of id 120 to 192.168.0.10 port 1645
	EAP-Message =
0x0104040a19c0000006f1160301004a0200004603014970a43d78dd332f6e7b648863347a1ce42c355ce4d73bc0d39f275d248c7e1f2049771b122c76f8f4a00bb4227b2d67d1fa90300f22e0b60a7891fae8ee5e7a92002f0016030106940b00069000068d0002cd308202c930820232a003020102020102300d06092a864886f70d010104050030819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f7374311b301906035504031312436c69656e74206365
	EAP-Message =
0x7274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d301e170d3034303132353133323631305a170d3035303132343133323631305a30819b310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f73743119301706035504031310526f6f74206365727469666963617465311f301d06092a864886f70d0109011610726f6f74406578616d706c652e636f6d30819f300d06092a864886f70d010101050003
	EAP-Message =
0x818d0030818902818100dac525422bfedb082629a2cba44b3449c90d0ab462fb72c8434a782098863d7eb7d7e70028c2b7ad555a51cc756cf4fa1d7091615ab450d5289553ae6616aff014a55085d6b8fb4aee98638e426175cdd36c665c63cda177d34920eb30585edc8773999c2980f81ad4638bbbea1c82d054023db7ef24a3ec1c3f6241a903d7f30203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d0101040500038181007a2d921b1cf13bf2982a9178ec9ede6d88edc178a2e8bd40a0a06fb6f0769957884cd7084537083496fd184165293f583c8e8240eb68e042c94b15752e4c07e80d09
	EAP-Message =
0x779afa3dd55c24fa54ac292d77205d1c2477ed30d59f57caf9bd21ff2a8d16cc0911c50e4f295763fcb60efa3c3d2d0e43850f6e6fbe284902f6e83503650003ba308203b63082031fa003020102020100300d06092a864886f70d010104050030819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f7374311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c
	EAP-Message = 0x652e636f6d301e170d3034303132353133323630375a
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xc6268f888323c9f0e7a30ccefba3b3cb
Fri Jan 16 16:14:05 2009 : Debug: Finished request 1
Fri Jan 16 16:14:05 2009 : Debug: Going to the next request
Fri Jan 16 16:14:05 2009 : Debug: Thread 2 waiting to be assigned a request
rad_recv: Access-Request packet from host 192.168.0.10:1645, id=121,
length=141
Fri Jan 16 16:14:05 2009 : Debug: Thread 3 got semaphore
Fri Jan 16 16:14:05 2009 : Debug: Thread 3 handling request 2, (1
handled so far)
	User-Name = "TEST\\ingo"
	Framed-MTU = 1400
	Called-Station-Id = "0014.1bb5.abe0"
	Calling-Station-Id = "001f.3ba6.c02f"
	Service-Type = Login-User
	Message-Authenticator = 0x9a963396a2f5c8712852d13eda7fa047
	EAP-Message = 0x020400061900
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 447
	State = 0xc6268f888323c9f0e7a30ccefba3b3cb
	NAS-IP-Address = 192.168.0.10
	NAS-Identifier = "ap"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
4 length 6
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 2
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 2
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 2
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Request found, released
from the list
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP/peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Authenticate
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: processing TLS
Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Received EAP-TLS ACK message
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: ack handshake fragment
handler
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_verify returned 1
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_process returned 13
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: EAPTLS_HANDLED
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 2
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns handled for request 2
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns handled) for request 2
Sending Access-Challenge of id 121 to 192.168.0.10 port 1645
	EAP-Message =
0x010502f71900170d3036303132343133323630375a30819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010060355040b13096c6f63616c686f7374311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100d4c5b19724f164acf1ffb189db1c8fbff4f14396ea7cb1e90f78d69451725377895dfe52ccb99b41e8
	EAP-Message =
0x0ddeb58b127a943f4f58cbc562878192fbdc6fece9f871e7c130d35cf5188817e9b133249edd2a1c75d31043ae87553cec7a77ef26aa7d74281db9b77e17c6446c5dd9b188b43250ca0229963722a123a726b00b4027fd0203010001a381ff3081fc301d0603551d0e0416041468d36d3e1ee7bc9d5a057021c363da1365d1ade33081cc0603551d230481c43081c1801468d36d3e1ee7bc9d5a057021c363da1365d1ade3a181a5a481a230819f310b30090603550406130243413111300f0603550408130850726f76696e63653112301006035504071309536f6d65204369747931153013060355040a130c4f7267616e697a6174696f6e31123010
	EAP-Message =
0x060355040b13096c6f63616c686f7374311b301906035504031312436c69656e742063657274696669636174653121301f06092a864886f70d0109011612636c69656e74406578616d706c652e636f6d820100300c0603551d13040530030101ff300d06092a864886f70d01010405000381810033c00b66b1e579ef73a06798252dab8d5e5511fc00fd276d80d12f834777c6743fdc2743fca1507704e4bc0979e4f60ac3ad9ee83e6f347369229d1f77229ba2e982359da563024a00163dba6d6c986c0bad28af85132ff8f0d76501bf1b7c2dff658ce1e62c01997b6e64e3e8d4373354ce9912847651539063b85bbc5485c516030100040e000000
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xc169e337667edbcff6bf7f69ebbcfc49
Fri Jan 16 16:14:05 2009 : Debug: Finished request 2
Fri Jan 16 16:14:05 2009 : Debug: Going to the next request
Fri Jan 16 16:14:05 2009 : Debug: Thread 3 waiting to be assigned a request
Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds...
rad_recv: Access-Request packet from host 192.168.0.10:1645, id=122,
length=343
Fri Jan 16 16:14:05 2009 : Debug: Thread 4 got semaphore
Fri Jan 16 16:14:05 2009 : Debug: Thread 4 handling request 3, (1
handled so far)
	User-Name = "TEST\\ingo"
	Framed-MTU = 1400
	Called-Station-Id = "0014.1bb5.abe0"
	Calling-Station-Id = "001f.3ba6.c02f"
	Service-Type = Login-User
	Message-Authenticator = 0xb27f2fdc11072b8abd17ce396a96e291
	EAP-Message =
0x020500d01980000000c6160301008610000082008004b963a40ee622d775f82f58e163cf262adad6bb6314eec472b6518be0f7a92daeeb9a59ef9470e6356765386cdb2dcdd423fa999d2564da9cb1fb9a51481d5c5b9b4f7cb28deb9301d451e5cd1c14f3f4decae2a60d851a75886993e9b84d4427b2b5a66e8d1cc83367e3bbe59123e798d864270f906dbb719f9f5ac019d51914030100010116030100309197bc5305f81c06f049831e54401892dea21c5aceeee70d50acf4adb201dca11da48f3da63a29d78fd500233eb850e7
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 447
	State = 0xc169e337667edbcff6bf7f69ebbcfc49
	NAS-IP-Address = 192.168.0.10
	NAS-Identifier = "ap"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
5 length 208
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 3
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 3
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 3
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Request found, released
from the list
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP/peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Authenticate
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: processing TLS
Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls:  Length Included
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_verify returned 11
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake
[length 0086], ClientKeyExchange
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 read client key
exchange A
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: <<< TLS 1.0
ChangeCipherSpec [length 0001]
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake
[length 0010], Finished
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 read finished A
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: >>> TLS 1.0
ChangeCipherSpec [length 0001]
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 write change
cipher spec A
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake
[length 0010], Finished
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 write finished A
Fri Jan 16 16:14:05 2009 : Debug:     TLS_accept: SSLv3 flush data
Fri Jan 16 16:14:05 2009 : Debug:     (other): SSL negotiation finished
successfully
Fri Jan 16 16:14:05 2009 : Debug: SSL Connection Established
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_process returned 13
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: EAPTLS_HANDLED
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 3
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns handled for request 3
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns handled) for request 3
Sending Access-Challenge of id 122 to 192.168.0.10 port 1645
	EAP-Message =
0x0106004119001403010001011603010030b39bf1c4a8799afd05f7cfb3a7886c2eb34c516f757a6f227bc8e9d0df34f2cbb1511cd2300d52108cdf79a3e3b0566f
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x448bc94717ef139356c77b3c4afde30a
Fri Jan 16 16:14:05 2009 : Debug: Finished request 3
Fri Jan 16 16:14:05 2009 : Debug: Going to the next request
Fri Jan 16 16:14:05 2009 : Debug: Thread 4 waiting to be assigned a request
Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds...
rad_recv: Access-Request packet from host 192.168.0.10:1645, id=123,
length=141
Fri Jan 16 16:14:05 2009 : Debug: Thread 5 got semaphore
Fri Jan 16 16:14:05 2009 : Debug: Thread 5 handling request 4, (1
handled so far)
	User-Name = "TEST\\ingo"
	Framed-MTU = 1400
	Called-Station-Id = "0014.1bb5.abe0"
	Calling-Station-Id = "001f.3ba6.c02f"
	Service-Type = Login-User
	Message-Authenticator = 0xfa9425d520d21ba586c035292bd68e07
	EAP-Message = 0x020600061900
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 447
	State = 0x448bc94717ef139356c77b3c4afde30a
	NAS-IP-Address = 192.168.0.10
	NAS-Identifier = "ap"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
6 length 6
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 4
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 4
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 4
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Request found, released
from the list
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP/peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Authenticate
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: processing TLS
Fri Jan 16 16:14:05 2009 : Debug: rlm_eap_tls: Received EAP-TLS ACK message
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: ack handshake is finished
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_verify returned 3
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_process returned 3
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: EAPTLS_SUCCESS
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 4
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns handled for request 4
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns handled) for request 4
Sending Access-Challenge of id 123 to 192.168.0.10 port 1645
	EAP-Message =
0x0107002b19001703010020358fa3be8c1b42a5648abf6663bbf31708f83b854ed45a2ee50b0070d2f5e4a6
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xbb9e5d984b6b1768046884bd3ccda3a9
Fri Jan 16 16:14:05 2009 : Debug: Finished request 4
Fri Jan 16 16:14:05 2009 : Debug: Going to the next request
Fri Jan 16 16:14:05 2009 : Debug: Thread 5 waiting to be assigned a request
Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds...
rad_recv: Access-Request packet from host 192.168.0.10:1645, id=124,
length=178
Fri Jan 16 16:14:05 2009 : Debug: Thread 1 got semaphore
Fri Jan 16 16:14:05 2009 : Debug: Thread 1 handling request 5, (2
handled so far)
	User-Name = "TEST\\ingo"
	Framed-MTU = 1400
	Called-Station-Id = "0014.1bb5.abe0"
	Calling-Station-Id = "001f.3ba6.c02f"
	Service-Type = Login-User
	Message-Authenticator = 0xdef3c12413c28597f3a7550b010e1faf
	EAP-Message =
0x0207002b19001703010020a8b1dda2c820274e487b7412c9ed15102f021fe8587d83588350f718066c156a
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 447
	State = 0xbb9e5d984b6b1768046884bd3ccda3a9
	NAS-IP-Address = 192.168.0.10
	NAS-Identifier = "ap"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
7 length 43
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 5
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 5
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 5
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Request found, released
from the list
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP/peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Authenticate
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: processing TLS
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_verify returned 7
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: Done initial handshake
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_process returned 7
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: EAPTLS_OK
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Session established.
Decoding tunneled attributes.
  PEAP tunnel data in 0000: 01 54 45 53 54 5c 69 6e 67 6f
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Identity - TEST\ingo
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Tunneled data is valid.
  PEAP: Got tunneled EAP-Message
	EAP-Message = 0x0207000e01544553545c696e676f
Fri Jan 16 16:14:05 2009 : Debug:   PEAP: Got tunneled identity of TEST\ingo
Fri Jan 16 16:14:05 2009 : Debug:   PEAP: Setting default EAP type for
tunneled EAP session.
Fri Jan 16 16:14:05 2009 : Debug:   PEAP: Setting User-Name to TEST\ingo
  PEAP: Sending tunneled request
	EAP-Message = 0x0207000e01544553545c696e676f
	FreeRADIUS-Proxied-To = 127.0.0.1
	User-Name = "TEST\\ingo"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
7 length 14
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 5
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 5
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 5
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP Identity
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type mschapv2
Fri Jan 16 16:14:05 2009 : Info: rlm_eap_mschapv2: Issuing Challenge
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns handled for request 5
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns handled) for request 5
  PEAP: Got tunneled reply RADIUS code 11
	EAP-Message =
0x010800231a0108001e109c2283a50e81eba9801ab35bfb7331d3544553545c696e676f
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x6ecfdf001baac997c755a948580aac74
  PEAP: Processing from tunneled session code 0xb8054c88 11
	EAP-Message =
0x010800231a0108001e109c2283a50e81eba9801ab35bfb7331d3544553545c696e676f
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x6ecfdf001baac997c755a948580aac74
Fri Jan 16 16:14:05 2009 : Debug:   PEAP: Got tunneled Access-Challenge
  PEAP tunnel data out 0000: 1a 01 08 00 1e 10 9c 22 83 a5 0e 81 eb a9
80 1a
  PEAP tunnel data out 0010: b3 5b fb 73 31 d3 54 45 53 54 5c 69 6e 67 6f
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 5
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns handled for request 5
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns handled) for request 5
Sending Access-Challenge of id 124 to 192.168.0.10 port 1645
	EAP-Message =
0x0108004b1900170301004066eb0a0f0b73febf4d7c2e9cc39ecb6eff47350707ddc6d69acf0644f6fdc6e115e82635e3be487f34063c41df74f2cbbbea8f72c9e3b6f556094b533d4fd4af
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x02687132de20b37319a88307f0faeae1
Fri Jan 16 16:14:05 2009 : Debug: Finished request 5
Fri Jan 16 16:14:05 2009 : Debug: Going to the next request
Fri Jan 16 16:14:05 2009 : Debug: Thread 1 waiting to be assigned a request
Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds...
rad_recv: Access-Request packet from host 192.168.0.10:1645, id=125,
length=242
Fri Jan 16 16:14:05 2009 : Debug: Thread 2 got semaphore
Fri Jan 16 16:14:05 2009 : Debug: Thread 2 handling request 6, (2
handled so far)
	User-Name = "TEST\\ingo"
	Framed-MTU = 1400
	Called-Station-Id = "0014.1bb5.abe0"
	Calling-Station-Id = "001f.3ba6.c02f"
	Service-Type = Login-User
	Message-Authenticator = 0xb919f5edbb443c7c81d91d535a38c317
	EAP-Message =
0x0208006b19001703010060d4fe15e2312afd8786e3a4db969bdf310aab5c52fc05ebc2b025bf25b053f18e565875f714a8962237b024779e724f8f6de423d67da9164de8951463da4c1155ae7823038b61a239686246b4a8ccaab645e9b645bb6bfbe3bb6353467ba53f77
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 447
	State = 0x02687132de20b37319a88307f0faeae1
	NAS-IP-Address = 192.168.0.10
	NAS-Identifier = "ap"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
8 length 107
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 6
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 6
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 6
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Request found, released
from the list
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP/peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Authenticate
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: processing TLS
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_verify returned 7
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: Done initial handshake
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_process returned 7
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: EAPTLS_OK
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Session established.
Decoding tunneled attributes.
  PEAP tunnel data in 0000: 1a 02 08 00 3f 31 93 4c e3 9a ee 6c 35 ae fb 16
  PEAP tunnel data in 0010: 5a 02 66 56 2c 02 00 00 00 00 00 00 00 00 02 5a
  PEAP tunnel data in 0020: f5 ee 1b 77 42 61 3e 7c 12 f0 df d0 1c eb 71 81
  PEAP tunnel data in 0030: 7a df 60 5d b5 85 00 54 45 53 54 5c 69 6e 67 6f
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: EAP type mschapv2
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Tunneled data is valid.
  PEAP: Got tunneled EAP-Message
	EAP-Message =
0x020800441a0208003f31934ce39aee6c35aefb165a0266562c020000000000000000025af5ee1b7742613e7c12f0dfd01ceb71817adf605db58500544553545c696e676f
Fri Jan 16 16:14:05 2009 : Debug:   PEAP: Setting User-Name to TEST\ingo
Fri Jan 16 16:14:05 2009 : Debug:   PEAP: Adding old state with 6e cf
  PEAP: Sending tunneled request
	EAP-Message =
0x020800441a0208003f31934ce39aee6c35aefb165a0266562c020000000000000000025af5ee1b7742613e7c12f0dfd01ceb71817adf605db58500544553545c696e676f
	FreeRADIUS-Proxied-To = 127.0.0.1
	User-Name = "TEST\\ingo"
	State = 0x6ecfdf001baac997c755a948580aac74
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
8 length 68
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 6
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 6
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 6
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Request found, released
from the list
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP/mschapv2
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type mschapv2
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group MS-CHAP for
request 6
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling
mschap (rlm_mschap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   rlm_mschap: No User-Password
configured.  Cannot create LM-Password.
Fri Jan 16 16:14:05 2009 : Debug:   rlm_mschap: No User-Password
configured.  Cannot create NT-Password.
Fri Jan 16 16:14:05 2009 : Debug:   rlm_mschap: Told to do MS-CHAPv2 for
ingo with NT-Password
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat:  '--username=TEST\\ingo'
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: Running registered xlat
function of module mschap for string 'Challenge'
Fri Jan 16 16:14:05 2009 : Debug:  mschap2: 9c
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat:
'--challenge=25226c1fad0393e9'
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat: Running registered xlat
function of module mschap for string 'NT-Response'
Fri Jan 16 16:14:05 2009 : Debug: radius_xlat:
'--nt-response=025af5ee1b7742613e7c12f0dfd01ceb71817adf605db585'
Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds...
Fri Jan 16 16:14:05 2009 : Debug: Threads: total/active/spare threads =
5/1/4
Fri Jan 16 16:14:05 2009 : Debug: Exec-Program output: Logon failure
(0xc000006d)
Fri Jan 16 16:14:05 2009 : Debug: Exec-Program-Wait: plaintext: Logon
failure (0xc000006d)
Fri Jan 16 16:14:05 2009 : Debug: Exec-Program: returned: 1
Fri Jan 16 16:14:05 2009 : Debug:   rlm_mschap: External script failed.
Fri Jan 16 16:14:05 2009 : Debug:   rlm_mschap: FAILED:
MS-CHAP2-Response is incorrect
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from mschap (rlm_mschap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module
"mschap" returns reject for request 6
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group MS-CHAP
(returns reject) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Freeing handler
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns reject for request 6
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns reject) for request 6
Fri Jan 16 16:14:05 2009 : Debug: auth: Failed to validate the user.
Fri Jan 16 16:14:05 2009 : Auth: Login incorrect (rlm_mschap: Logon
failure (0xc000006d)): [TEST\\ingo/<no User-Password attribute>] (from
client localhost port 0)
  PEAP: Got tunneled reply RADIUS code 3
	MS-CHAP-Error = "\010E=691 R=1"
	EAP-Message = 0x04080004
	Message-Authenticator = 0x00000000000000000000000000000000
  PEAP: Processing from tunneled session code 0xb802fb38 3
	MS-CHAP-Error = "\010E=691 R=1"
	EAP-Message = 0x04080004
	Message-Authenticator = 0x00000000000000000000000000000000
Fri Jan 16 16:14:05 2009 : Debug:   PEAP: Tunneled authentication was
rejected.
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: FAILURE
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 6
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns handled for request 6
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns handled) for request 6
Sending Access-Challenge of id 125 to 192.168.0.10 port 1645
	EAP-Message =
0x0109002b190017030100208aa1588bd73ef98e213f02c61510d6b5f9c87bd67d5e78c82f44b534469acf8a
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x6d48ffddf81c42eee19afc937d511616
Fri Jan 16 16:14:05 2009 : Debug: Finished request 6
Fri Jan 16 16:14:05 2009 : Debug: Going to the next request
Fri Jan 16 16:14:05 2009 : Debug: Thread 2 waiting to be assigned a request
rad_recv: Access-Request packet from host 192.168.0.10:1645, id=126,
length=178
Fri Jan 16 16:14:05 2009 : Debug: Waking up in 31 seconds...
Fri Jan 16 16:14:05 2009 : Debug: Threads: total/active/spare threads =
5/0/5
Fri Jan 16 16:14:05 2009 : Debug: Thread 3 got semaphore
Fri Jan 16 16:14:05 2009 : Debug: Thread 3 handling request 7, (2
handled so far)
	User-Name = "TEST\\ingo"
	Framed-MTU = 1400
	Called-Station-Id = "0014.1bb5.abe0"
	Calling-Station-Id = "001f.3ba6.c02f"
	Service-Type = Login-User
	Message-Authenticator = 0xd451d8a691c8df289e6318ddca2ca21f
	EAP-Message =
0x0209002b190017030100207a8219bad919c0e15ca4c4226cc59c5925aff5c81c8bfb5e0f5e066956224158
	NAS-Port-Type = Wireless-802.11
	NAS-Port = 447
	State = 0x6d48ffddf81c42eee19afc937d511616
	NAS-IP-Address = 192.168.0.10
	NAS-Identifier = "ap"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authorize section of
radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authorize for
request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module
"preprocess" returns ok for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "chap"
returns noop for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP packet type response id
9 length 43
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: No EAP Start, assuming it's
an on-going EAP conversation
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
eap (rlm_eap) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "eap"
returns updated for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 7
Fri Jan 16 16:14:05 2009 : Debug:     users: Matched entry DEFAULT at
line 153
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "files"
returns ok for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 7
Fri Jan 16 16:14:05 2009 : Debug: rlm_pap: WARNING! No "known good"
password found for the user.  Authentication may fail because of this.
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authorize]: returned from
pap (rlm_pap) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authorize]: module "pap"
returns noop for request 7
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authorize
(returns updated) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   rad_check_password:  Found Auth-Type EAP
Fri Jan 16 16:14:05 2009 : Debug: auth: type "EAP"
Fri Jan 16 16:14:05 2009 : Debug:   Processing the authenticate section
of radiusd.conf
Fri Jan 16 16:14:05 2009 : Debug: modcall: entering group authenticate
for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: calling eap
(rlm_eap) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Request found, released
from the list
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: EAP/peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: processing type peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Authenticate
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: processing TLS
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_verify returned 7
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_tls: Done initial handshake
Fri Jan 16 16:14:05 2009 : Debug:   eaptls_process returned 7
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: EAPTLS_OK
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Session established.
Decoding tunneled attributes.
  PEAP tunnel data in 0000: 02 09 00 0b 21 80 03 00 02 00 02
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Received EAP-TLV response.
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap: Tunneled data is valid.
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap_peap:  Had sent TLV failure.
 User was rejcted rejected earlier in this session.
Fri Jan 16 16:14:05 2009 : Debug:  rlm_eap: Handler failed in EAP/peap
Fri Jan 16 16:14:05 2009 : Debug:   rlm_eap: Failed in EAP select
Fri Jan 16 16:14:05 2009 : Debug:   modsingle[authenticate]: returned
from eap (rlm_eap) for request 7
Fri Jan 16 16:14:05 2009 : Debug:   modcall[authenticate]: module "eap"
returns invalid for request 7
Fri Jan 16 16:14:05 2009 : Debug: modcall: leaving group authenticate
(returns invalid) for request 7
Fri Jan 16 16:14:05 2009 : Debug: auth: Failed to validate the user.
Fri Jan 16 16:14:05 2009 : Auth: Login incorrect: [TEST\\ingo/<no
User-Password attribute>] (from client 192.168.0.10 port 447 cli
001f.3ba6.c02f)
Fri Jan 16 16:14:05 2009 : Debug: Delaying request 7 for 1 seconds
Fri Jan 16 16:14:05 2009 : Debug: Finished request 7
Fri Jan 16 16:14:05 2009 : Debug: Going to the next request
Fri Jan 16 16:14:05 2009 : Debug: Thread 3 waiting to be assigned a request
rad_recv: Access-Request packet from host 192.168.0.10:1645, id=126,
length=178
Sending Access-Reject of id 126 to 192.168.0.10 port 1645
	EAP-Message = 0x04090004
	Message-Authenticator = 0x00000000000000000000000000000000
Fri Jan 16 16:14:10 2009 : Debug: --- Walking the entire request list ---
Fri Jan 16 16:14:10 2009 : Debug: Waking up in 1 seconds...
Fri Jan 16 16:14:11 2009 : Debug: --- Walking the entire request list ---
Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 0 ID 119 with
timestamp 4970a43d
Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 1 ID 120 with
timestamp 4970a43d
Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 2 ID 121 with
timestamp 4970a43d
Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 3 ID 122 with
timestamp 4970a43d
Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 4 ID 123 with
timestamp 4970a43d
Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 5 ID 124 with
timestamp 4970a43d
Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 6 ID 125 with
timestamp 4970a43d
Fri Jan 16 16:14:11 2009 : Debug: Cleaning up request 7 ID 126 with
timestamp 4970a43d
Fri Jan 16 16:14:11 2009 : Debug: Nothing to do.  Sleeping until we see
a request.

ntlm_auth not working from within Freeradius with Domain in Username

Holger Steppke