Wed Jul  4 16:59:36 2007 : Info: Starting - reading configuration files ...
Wed Jul  4 16:59:36 2007 : Debug: reread_config:  reading radiusd.conf
Wed Jul  4 16:59:36 2007 : Debug: Config:   including file: /etc/freeradius/proxy.conf
Wed Jul  4 16:59:36 2007 : Debug: Config:   including file: /etc/freeradius/clients.conf
Wed Jul  4 16:59:36 2007 : Debug: Config:   including file: /etc/freeradius/snmp.conf
Wed Jul  4 16:59:36 2007 : Debug: Config:   including file: /etc/freeradius/eap.conf
Wed Jul  4 16:59:36 2007 : Debug: Config:   including file: /etc/freeradius/sql.conf
Wed Jul  4 16:59:36 2007 : Debug:  main: prefix = "/usr"
Wed Jul  4 16:59:36 2007 : Debug:  main: localstatedir = "/var"
Wed Jul  4 16:59:36 2007 : Debug:  main: logdir = "/var/log/freeradius"
Wed Jul  4 16:59:36 2007 : Debug:  main: libdir = "/usr/lib/freeradius"
Wed Jul  4 16:59:36 2007 : Debug:  main: radacctdir = "/var/log/freeradius/radacct"
Wed Jul  4 16:59:36 2007 : Debug:  main: hostname_lookups = no
Wed Jul  4 16:59:36 2007 : Debug:  main: max_request_time = 30
Wed Jul  4 16:59:36 2007 : Debug:  main: cleanup_delay = 5
Wed Jul  4 16:59:36 2007 : Debug:  main: max_requests = 1024
Wed Jul  4 16:59:36 2007 : Debug:  main: delete_blocked_requests = 0
Wed Jul  4 16:59:36 2007 : Debug:  main: port = 0
Wed Jul  4 16:59:36 2007 : Debug:  main: allow_core_dumps = no
Wed Jul  4 16:59:36 2007 : Debug:  main: log_stripped_names = no
Wed Jul  4 16:59:36 2007 : Debug:  main: log_file = "/var/log/freeradius/radius.log"
Wed Jul  4 16:59:36 2007 : Debug:  main: log_auth = no
Wed Jul  4 16:59:36 2007 : Debug:  main: log_auth_badpass = no
Wed Jul  4 16:59:36 2007 : Debug:  main: log_auth_goodpass = no
Wed Jul  4 16:59:36 2007 : Debug:  main: pidfile = "/var/run/freeradius/freeradius.pid"
Wed Jul  4 16:59:36 2007 : Debug:  main: user = "freerad"
Wed Jul  4 16:59:36 2007 : Debug:  main: group = "freerad"
Wed Jul  4 16:59:36 2007 : Debug:  main: usercollide = no
Wed Jul  4 16:59:36 2007 : Debug:  main: lower_user = "no"
Wed Jul  4 16:59:36 2007 : Debug:  main: lower_pass = "no"
Wed Jul  4 16:59:36 2007 : Debug:  main: nospace_user = "no"
Wed Jul  4 16:59:36 2007 : Debug:  main: nospace_pass = "no"
Wed Jul  4 16:59:36 2007 : Debug:  main: checkrad = "/usr/sbin/checkrad"
Wed Jul  4 16:59:36 2007 : Debug:  main: proxy_requests = yes
Wed Jul  4 16:59:36 2007 : Debug:  proxy: retry_delay = 5
Wed Jul  4 16:59:36 2007 : Debug:  proxy: retry_count = 3
Wed Jul  4 16:59:36 2007 : Debug:  proxy: synchronous = no
Wed Jul  4 16:59:36 2007 : Debug:  proxy: default_fallback = yes
Wed Jul  4 16:59:36 2007 : Debug:  proxy: dead_time = 120
Wed Jul  4 16:59:36 2007 : Debug:  proxy: post_proxy_authorize = no
Wed Jul  4 16:59:36 2007 : Debug:  proxy: wake_all_if_all_dead = no
Wed Jul  4 16:59:36 2007 : Debug:  security: max_attributes = 200
Wed Jul  4 16:59:36 2007 : Debug:  security: reject_delay = 1
Wed Jul  4 16:59:36 2007 : Debug:  security: status_server = no
Wed Jul  4 16:59:36 2007 : Debug:  main: debug_level = 0
Wed Jul  4 16:59:36 2007 : Debug: read_config_files:  reading dictionary
Wed Jul  4 16:59:36 2007 : Debug: read_config_files:  reading naslist
Wed Jul  4 16:59:36 2007 : Info: Using deprecated naslist file.  Support for this will go away soon.
Wed Jul  4 16:59:36 2007 : Debug: read_config_files:  reading clients
Wed Jul  4 16:59:36 2007 : Debug: read_config_files:  reading realms
Wed Jul  4 16:59:36 2007 : Debug: radiusd:  entering modules setup
Wed Jul  4 16:59:36 2007 : Debug: Module: Library search path is /usr/lib/freeradius
Wed Jul  4 16:59:36 2007 : Debug: Module: Loaded exec 
Wed Jul  4 16:59:36 2007 : Debug:  exec: wait = yes
Wed Jul  4 16:59:36 2007 : Debug:  exec: program = "(null)"
Wed Jul  4 16:59:36 2007 : Debug:  exec: input_pairs = "request"
Wed Jul  4 16:59:36 2007 : Debug:  exec: output_pairs = "(null)"
Wed Jul  4 16:59:36 2007 : Debug:  exec: packet_type = "(null)"
Wed Jul  4 16:59:36 2007 : Info: rlm_exec: Wait=yes but no output defined. Did you mean output=none?
Wed Jul  4 16:59:36 2007 : Debug: Module: Instantiated exec (exec) 
Wed Jul  4 16:59:36 2007 : Debug: Module: Loaded expr 
Wed Jul  4 16:59:36 2007 : Debug: Module: Instantiated expr (expr) 
Wed Jul  4 16:59:36 2007 : Debug: Module: Loaded PAP 
Wed Jul  4 16:59:36 2007 : Debug:  pap: encryption_scheme = "crypt"
Wed Jul  4 16:59:36 2007 : Debug:  pap: auto_header = yes
Wed Jul  4 16:59:36 2007 : Debug: Module: Instantiated pap (pap) 
Wed Jul  4 16:59:36 2007 : Debug: Module: Loaded CHAP 
Wed Jul  4 16:59:36 2007 : Debug: Module: Instantiated chap (chap) 
Wed Jul  4 16:59:36 2007 : Debug: Module: Loaded MS-CHAP 
Wed Jul  4 16:59:36 2007 : Debug:  mschap: use_mppe = yes
Wed Jul  4 16:59:36 2007 : Debug:  mschap: require_encryption = no
Wed Jul  4 16:59:36 2007 : Debug:  mschap: require_strong = no
Wed Jul  4 16:59:36 2007 : Debug:  mschap: with_ntdomain_hack = no
Wed Jul  4 16:59:36 2007 : Debug:  mschap: passwd = "(null)"
Wed Jul  4 16:59:36 2007 : Debug:  mschap: ntlm_auth = "(null)"
Wed Jul  4 16:59:36 2007 : Debug: Module: Instantiated mschap (mschap) 
Wed Jul  4 16:59:36 2007 : Debug: Module: Loaded System 
Wed Jul  4 16:59:36 2007 : Debug:  unix: cache = no
Wed Jul  4 16:59:36 2007 : Debug:  unix: passwd = "(null)"
Wed Jul  4 16:59:36 2007 : Debug:  unix: shadow = "/etc/shadow"
Wed Jul  4 16:59:36 2007 : Debug:  unix: group = "(null)"
Wed Jul  4 16:59:36 2007 : Debug:  unix: radwtmp = "/var/log/freeradius/radwtmp"
Wed Jul  4 16:59:36 2007 : Debug:  unix: usegroup = no
Wed Jul  4 16:59:36 2007 : Debug:  unix: cache_reload = 600
Wed Jul  4 16:59:36 2007 : Debug: Module: Instantiated unix (unix) 
Wed Jul  4 16:59:36 2007 : Debug: Module: Loaded eap 
Wed Jul  4 16:59:36 2007 : Debug:  eap: default_eap_type = "md5"
Wed Jul  4 16:59:36 2007 : Debug:  eap: timer_expire = 60
Wed Jul  4 16:59:36 2007 : Debug:  eap: ignore_unknown_eap_types = no
Wed Jul  4 16:59:36 2007 : Debug:  eap: cisco_accounting_username_bug = no
Wed Jul  4 16:59:36 2007 : Debug: rlm_eap: Loaded and initialized type md5
Wed Jul  4 16:59:36 2007 : Debug: rlm_eap: Loaded and initialized type leap
Wed Jul  4 16:59:36 2007 : Debug:  gtc: challenge = "Password: "
Wed Jul  4 16:59:36 2007 : Debug:  gtc: auth_type = "PAP"
Wed Jul  4 16:59:36 2007 : Debug: rlm_eap: Loaded and initialized type gtc
Wed Jul  4 16:59:36 2007 : Debug:  tls: rsa_key_exchange = no
Wed Jul  4 16:59:36 2007 : Debug:  tls: dh_key_exchange = yes
Wed Jul  4 16:59:36 2007 : Debug:  tls: rsa_key_length = 512
Wed Jul  4 16:59:36 2007 : Debug:  tls: dh_key_length = 512
Wed Jul  4 16:59:36 2007 : Debug:  tls: verify_depth = 0
Wed Jul  4 16:59:36 2007 : Debug:  tls: CA_path = "(null)"
Wed Jul  4 16:59:36 2007 : Debug:  tls: pem_file_type = yes
Wed Jul  4 16:59:36 2007 : Debug:  tls: private_key_file = "/etc/freeradius/certs/CERT/cert-srv.pem"
Wed Jul  4 16:59:36 2007 : Debug:  tls: certificate_file = "/etc/freeradius/certs/CERT/cert-srv.pem"
Wed Jul  4 16:59:36 2007 : Debug:  tls: CA_file = "/etc/freeradius/certs/CERT/root.pem"
Wed Jul  4 16:59:36 2007 : Debug:  tls: private_key_password = "BLStream"
Wed Jul  4 16:59:36 2007 : Debug:  tls: dh_file = "/etc/freeradius/certs/CERT/dh"
Wed Jul  4 16:59:36 2007 : Debug:  tls: random_file = "/dev/urandom"
Wed Jul  4 16:59:36 2007 : Debug:  tls: fragment_size = 1024
Wed Jul  4 16:59:36 2007 : Debug:  tls: include_length = yes
Wed Jul  4 16:59:36 2007 : Debug:  tls: check_crl = no
Wed Jul  4 16:59:36 2007 : Debug:  tls: check_cert_cn = "(null)"
Wed Jul  4 16:59:36 2007 : Debug:  tls: cipher_list = "(null)"
Wed Jul  4 16:59:36 2007 : Debug:  tls: check_cert_issuer = "(null)"
Wed Jul  4 16:59:36 2007 : Info: rlm_eap_tls: Loading the certificate file as a chain
Wed Jul  4 16:59:37 2007 : Debug: rlm_eap: Loaded and initialized type tls
Wed Jul  4 16:59:37 2007 : Debug:  ttls: default_eap_type = "md5"
Wed Jul  4 16:59:37 2007 : Debug:  ttls: copy_request_to_tunnel = no
Wed Jul  4 16:59:37 2007 : Debug:  ttls: use_tunneled_reply = no
Wed Jul  4 16:59:37 2007 : Debug: rlm_eap: Loaded and initialized type ttls
Wed Jul  4 16:59:37 2007 : Debug:  peap: default_eap_type = "mschapv2"
Wed Jul  4 16:59:37 2007 : Debug:  peap: copy_request_to_tunnel = no
Wed Jul  4 16:59:37 2007 : Debug:  peap: use_tunneled_reply = no
Wed Jul  4 16:59:37 2007 : Debug:  peap: proxy_tunneled_request_as_eap = yes
Wed Jul  4 16:59:37 2007 : Debug: rlm_eap: Loaded and initialized type peap
Wed Jul  4 16:59:37 2007 : Debug:  mschapv2: with_ntdomain_hack = no
Wed Jul  4 16:59:37 2007 : Debug: rlm_eap: Loaded and initialized type mschapv2
Wed Jul  4 16:59:37 2007 : Debug: Module: Instantiated eap (eap) 
Wed Jul  4 16:59:37 2007 : Debug: Module: Loaded preprocess 
Wed Jul  4 16:59:37 2007 : Debug:  preprocess: huntgroups = "/etc/freeradius/huntgroups"
Wed Jul  4 16:59:37 2007 : Debug:  preprocess: hints = "/etc/freeradius/hints"
Wed Jul  4 16:59:37 2007 : Debug:  preprocess: with_ascend_hack = no
Wed Jul  4 16:59:37 2007 : Debug:  preprocess: ascend_channels_per_line = 23
Wed Jul  4 16:59:37 2007 : Debug:  preprocess: with_ntdomain_hack = no
Wed Jul  4 16:59:37 2007 : Debug:  preprocess: with_specialix_jetstream_hack = no
Wed Jul  4 16:59:37 2007 : Debug:  preprocess: with_cisco_vsa_hack = no
Wed Jul  4 16:59:37 2007 : Debug:  preprocess: with_alvarion_vsa_hack = no
Wed Jul  4 16:59:37 2007 : Debug: Module: Instantiated preprocess (preprocess) 
Wed Jul  4 16:59:37 2007 : Debug: Module: Loaded realm 
Wed Jul  4 16:59:37 2007 : Debug:  realm: format = "suffix"
Wed Jul  4 16:59:37 2007 : Debug:  realm: delimiter = "@"
Wed Jul  4 16:59:37 2007 : Debug:  realm: ignore_default = no
Wed Jul  4 16:59:37 2007 : Debug:  realm: ignore_null = no
Wed Jul  4 16:59:37 2007 : Debug: Module: Instantiated realm (suffix) 
Wed Jul  4 16:59:37 2007 : Debug: Module: Loaded files 
Wed Jul  4 16:59:37 2007 : Debug:  files: usersfile = "/etc/freeradius/users"
Wed Jul  4 16:59:37 2007 : Debug:  files: acctusersfile = "/etc/freeradius/acct_users"
Wed Jul  4 16:59:37 2007 : Debug:  files: preproxy_usersfile = "/etc/freeradius/preproxy_users"
Wed Jul  4 16:59:37 2007 : Debug:  files: compat = "no"
Wed Jul  4 16:59:37 2007 : Debug: Module: Instantiated files (files) 
Wed Jul  4 16:59:37 2007 : Debug: Module: Loaded Acct-Unique-Session-Id 
Wed Jul  4 16:59:37 2007 : Debug:  acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Wed Jul  4 16:59:37 2007 : Debug: Module: Instantiated acct_unique (acct_unique) 
Wed Jul  4 16:59:37 2007 : Debug: Module: Loaded detail 
Wed Jul  4 16:59:37 2007 : Debug:  detail: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Wed Jul  4 16:59:37 2007 : Debug:  detail: detailperm = 384
Wed Jul  4 16:59:37 2007 : Debug:  detail: dirperm = 493
Wed Jul  4 16:59:37 2007 : Debug:  detail: locking = no
Wed Jul  4 16:59:37 2007 : Debug: Module: Instantiated detail (detail) 
Wed Jul  4 16:59:37 2007 : Debug: Module: Loaded radutmp 
Wed Jul  4 16:59:37 2007 : Debug:  radutmp: filename = "/var/log/freeradius/radutmp"
Wed Jul  4 16:59:37 2007 : Debug:  radutmp: username = "%{User-Name}"
Wed Jul  4 16:59:37 2007 : Debug:  radutmp: case_sensitive = yes
Wed Jul  4 16:59:37 2007 : Debug:  radutmp: check_with_nas = yes
Wed Jul  4 16:59:37 2007 : Debug:  radutmp: perm = 384
Wed Jul  4 16:59:37 2007 : Debug:  radutmp: callerid = yes
Wed Jul  4 16:59:37 2007 : Debug: Module: Instantiated radutmp (radutmp) 
Wed Jul  4 16:59:37 2007 : Debug: Listening on authentication *:1812
Wed Jul  4 16:59:37 2007 : Debug: Listening on accounting *:1813
Wed Jul  4 16:59:37 2007 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 192.168.0.101:5001, id=48, length=113
	User-Name = "windows"
	EAP-Message = 0x0201000c0177696e646f7773
	Message-Authenticator = 0x444d8e6faba64d1e2bb7a312881af4de
	NAS-IP-Address = 192.168.0.101
	NAS-Identifier = "4500"
	NAS-Port = 268533761
	NAS-Port-Type = Ethernet
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Calling-Station-Id = "0017-a4e1-2c86"
Wed Jul  4 16:59:45 2007 : Debug:   Processing the authorize section of radiusd.conf
Wed Jul  4 16:59:45 2007 : Debug: modcall: entering group authorize for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "chap" returns noop for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "mschap" returns noop for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 0
Wed Jul  4 16:59:45 2007 : Debug:     rlm_realm: No '@' in User-Name = "windows", looking up realm NULL
Wed Jul  4 16:59:45 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "suffix" returns noop for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap: EAP packet type response id 1 length 12
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "eap" returns updated for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 0
Wed Jul  4 16:59:45 2007 : Debug:     users: Matched entry DEFAULT at line 153
Wed Jul  4 16:59:45 2007 : Debug:     users: Matched entry DEFAULT at line 172
Wed Jul  4 16:59:45 2007 : Debug:     users: Matched entry DEFAULT at line 184
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "files" returns ok for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 0
Wed Jul  4 16:59:45 2007 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "pap" returns noop for request 0
Wed Jul  4 16:59:45 2007 : Debug: modcall: leaving group authorize (returns updated) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jul  4 16:59:45 2007 : Debug: auth: type "EAP"
Wed Jul  4 16:59:45 2007 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jul  4 16:59:45 2007 : Debug: modcall: entering group authenticate for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap: EAP Identity
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap: processing type md5
Wed Jul  4 16:59:45 2007 : Info: rlm_eap_md5: Issuing Challenge
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 0
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authenticate]: module "eap" returns handled for request 0
Wed Jul  4 16:59:45 2007 : Debug: modcall: leaving group authenticate (returns handled) for request 0
Sending Access-Challenge of id 48 to 192.168.0.101 port 5001
	Framed-IP-Address = 255.255.255.254
	Framed-MTU = 576
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Framed-Compression = Van-Jacobson-TCP-IP
	EAP-Message = 0x0102001604107e221326be214a5fe9d6289619b535d9
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x83e9e226d093fd3a34a1b8aa9cf3cc66
Wed Jul  4 16:59:45 2007 : Debug: Finished request 0
Wed Jul  4 16:59:45 2007 : Debug: Going to the next request
Wed Jul  4 16:59:45 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 16:59:45 2007 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.101:5001, id=49, length=125
	User-Name = "windows"
	EAP-Message = 0x020200060315
	Message-Authenticator = 0x21527f75b96370cc339d961533f147bc
	NAS-IP-Address = 192.168.0.101
	NAS-Identifier = "4500"
	NAS-Port = 268533761
	NAS-Port-Type = Ethernet
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Calling-Station-Id = "0017-a4e1-2c86"
	State = 0x83e9e226d093fd3a34a1b8aa9cf3cc66
Wed Jul  4 16:59:45 2007 : Debug:   Processing the authorize section of radiusd.conf
Wed Jul  4 16:59:45 2007 : Debug: modcall: entering group authorize for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "chap" returns noop for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "mschap" returns noop for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 1
Wed Jul  4 16:59:45 2007 : Debug:     rlm_realm: No '@' in User-Name = "windows", looking up realm NULL
Wed Jul  4 16:59:45 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "suffix" returns noop for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap: EAP packet type response id 2 length 6
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "eap" returns updated for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 1
Wed Jul  4 16:59:45 2007 : Debug:     users: Matched entry DEFAULT at line 153
Wed Jul  4 16:59:45 2007 : Debug:     users: Matched entry DEFAULT at line 172
Wed Jul  4 16:59:45 2007 : Debug:     users: Matched entry DEFAULT at line 184
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "files" returns ok for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 1
Wed Jul  4 16:59:45 2007 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authorize]: module "pap" returns noop for request 1
Wed Jul  4 16:59:45 2007 : Debug: modcall: leaving group authorize (returns updated) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jul  4 16:59:45 2007 : Debug: auth: type "EAP"
Wed Jul  4 16:59:45 2007 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jul  4 16:59:45 2007 : Debug: modcall: entering group authenticate for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap: Request found, released from the list
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap: EAP NAK
Wed Jul  4 16:59:45 2007 : Debug:  rlm_eap: EAP-NAK asked for EAP-Type/ttls
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap: processing type tls
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap_tls: Initiate
Wed Jul  4 16:59:45 2007 : Debug:   rlm_eap_tls: Start returned 1
Wed Jul  4 16:59:45 2007 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 1
Wed Jul  4 16:59:45 2007 : Debug:   modcall[authenticate]: module "eap" returns handled for request 1
Wed Jul  4 16:59:45 2007 : Debug: modcall: leaving group authenticate (returns handled) for request 1
Sending Access-Challenge of id 49 to 192.168.0.101 port 5001
	Framed-IP-Address = 255.255.255.254
	Framed-MTU = 576
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Framed-Compression = Van-Jacobson-TCP-IP
	EAP-Message = 0x010300061520
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xd94d2390e46b7e7424967ddc53d6e624
Wed Jul  4 16:59:45 2007 : Debug: Finished request 1
Wed Jul  4 16:59:45 2007 : Debug: Going to the next request
Wed Jul  4 16:59:45 2007 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.101:5001, id=50, length=179
	User-Name = "windows"
	EAP-Message = 0x0203003c158000000032160301002d01000029030194cf2d38f93c284f79a1da60ce7d2c4b6371b9710ab09c9b0139575ac062630a000002000a0100
	Message-Authenticator = 0x1ab6f00ffd25073472cc1f9c29402dd9
	NAS-IP-Address = 192.168.0.101
	NAS-Identifier = "4500"
	NAS-Port = 268533761
	NAS-Port-Type = Ethernet
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Calling-Station-Id = "0017-a4e1-2c86"
	State = 0xd94d2390e46b7e7424967ddc53d6e624
Wed Jul  4 16:59:46 2007 : Debug:   Processing the authorize section of radiusd.conf
Wed Jul  4 16:59:46 2007 : Debug: modcall: entering group authorize for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modcall[authorize]: module "chap" returns noop for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modcall[authorize]: module "mschap" returns noop for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 2
Wed Jul  4 16:59:46 2007 : Debug:     rlm_realm: No '@' in User-Name = "windows", looking up realm NULL
Wed Jul  4 16:59:46 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modcall[authorize]: module "suffix" returns noop for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap: EAP packet type response id 3 length 60
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modcall[authorize]: module "eap" returns updated for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 2
Wed Jul  4 16:59:46 2007 : Debug:     users: Matched entry DEFAULT at line 153
Wed Jul  4 16:59:46 2007 : Debug:     users: Matched entry DEFAULT at line 172
Wed Jul  4 16:59:46 2007 : Debug:     users: Matched entry DEFAULT at line 184
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modcall[authorize]: module "files" returns ok for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 2
Wed Jul  4 16:59:46 2007 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modcall[authorize]: module "pap" returns noop for request 2
Wed Jul  4 16:59:46 2007 : Debug: modcall: leaving group authorize (returns updated) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jul  4 16:59:46 2007 : Debug: auth: type "EAP"
Wed Jul  4 16:59:46 2007 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jul  4 16:59:46 2007 : Debug: modcall: entering group authenticate for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap: Request found, released from the list
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap: EAP/ttls
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap: processing type ttls
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap_ttls: Authenticate
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap_tls: processing TLS
Wed Jul  4 16:59:46 2007 : Debug: rlm_eap_tls:  Length Included
Wed Jul  4 16:59:46 2007 : Debug:   eaptls_verify returned 11 
Wed Jul  4 16:59:46 2007 : Debug:     (other): before/accept initialization 
Wed Jul  4 16:59:46 2007 : Debug:     TLS_accept: before/accept initialization 
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake [length 002d], ClientHello  
Wed Jul  4 16:59:46 2007 : Debug:     TLS_accept: SSLv3 read client hello A 
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake [length 004a], ServerHello  
Wed Jul  4 16:59:46 2007 : Debug:     TLS_accept: SSLv3 write server hello A 
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake [length 0277], Certificate  
Wed Jul  4 16:59:46 2007 : Debug:     TLS_accept: SSLv3 write certificate A 
Wed Jul  4 16:59:46 2007 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone  
Wed Jul  4 16:59:46 2007 : Debug:     TLS_accept: SSLv3 write server done A 
Wed Jul  4 16:59:46 2007 : Debug:     TLS_accept: SSLv3 flush data 
Wed Jul  4 16:59:46 2007 : Debug:     TLS_accept: Need to read more data: SSLv3 read client certificate A
Wed Jul  4 16:59:46 2007 : Debug: In SSL Handshake Phase 
Wed Jul  4 16:59:46 2007 : Debug: In SSL Accept mode  
Wed Jul  4 16:59:46 2007 : Debug:   eaptls_process returned 13 
Wed Jul  4 16:59:46 2007 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 2
Wed Jul  4 16:59:46 2007 : Debug:   modcall[authenticate]: module "eap" returns handled for request 2
Wed Jul  4 16:59:46 2007 : Debug: modcall: leaving group authenticate (returns handled) for request 2
Sending Access-Challenge of id 50 to 192.168.0.101 port 5001
	Framed-IP-Address = 255.255.255.254
	Framed-MTU = 576
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Framed-Compression = Van-Jacobson-TCP-IP
	EAP-Message = [payload removed: 508 characters]
	EAP-Message = [payload removed: 508 characters]
	EAP-Message = [payload removed: 458 characters]
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xe4fb85c1d069ea7c3edc9d62c438dbd3
Wed Jul  4 16:59:46 2007 : Debug: Finished request 2
Wed Jul  4 16:59:46 2007 : Debug: Going to the next request
Wed Jul  4 16:59:46 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 16:59:46 2007 : Debug: Waking up in 5 seconds...
rad_recv: Access-Request packet from host 192.168.0.101:5001, id=51, length=319
	User-Name = "windows"
	EAP-Message = [payload removed: 402 characters]
	Message-Authenticator = 0x92397db0cbc22142c0ae0e125ed28b25
	NAS-IP-Address = 192.168.0.101
	NAS-Identifier = "4500"
	NAS-Port = 268533761
	NAS-Port-Type = Ethernet
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Calling-Station-Id = "0017-a4e1-2c86"
	State = 0xe4fb85c1d069ea7c3edc9d62c438dbd3
Wed Jul  4 16:59:47 2007 : Debug:   Processing the authorize section of radiusd.conf
Wed Jul  4 16:59:47 2007 : Debug: modcall: entering group authorize for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modcall[authorize]: module "chap" returns noop for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modcall[authorize]: module "mschap" returns noop for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 3
Wed Jul  4 16:59:47 2007 : Debug:     rlm_realm: No '@' in User-Name = "windows", looking up realm NULL
Wed Jul  4 16:59:47 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modcall[authorize]: module "suffix" returns noop for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap: EAP packet type response id 4 length 200
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modcall[authorize]: module "eap" returns updated for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 3
Wed Jul  4 16:59:47 2007 : Debug:     users: Matched entry DEFAULT at line 153
Wed Jul  4 16:59:47 2007 : Debug:     users: Matched entry DEFAULT at line 172
Wed Jul  4 16:59:47 2007 : Debug:     users: Matched entry DEFAULT at line 184
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modcall[authorize]: module "files" returns ok for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 3
Wed Jul  4 16:59:47 2007 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modcall[authorize]: module "pap" returns noop for request 3
Wed Jul  4 16:59:47 2007 : Debug: modcall: leaving group authorize (returns updated) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jul  4 16:59:47 2007 : Debug: auth: type "EAP"
Wed Jul  4 16:59:47 2007 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jul  4 16:59:47 2007 : Debug: modcall: entering group authenticate for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap: Request found, released from the list
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap: EAP/ttls
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap: processing type ttls
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap_ttls: Authenticate
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap_tls: processing TLS
Wed Jul  4 16:59:47 2007 : Debug: rlm_eap_tls:  Length Included
Wed Jul  4 16:59:47 2007 : Debug:   eaptls_verify returned 11 
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange  
Wed Jul  4 16:59:47 2007 : Debug:     TLS_accept: SSLv3 read client key exchange A 
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001]  
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished  
Wed Jul  4 16:59:47 2007 : Debug:     TLS_accept: SSLv3 read finished A 
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001]  
Wed Jul  4 16:59:47 2007 : Debug:     TLS_accept: SSLv3 write change cipher spec A 
Wed Jul  4 16:59:47 2007 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished  
Wed Jul  4 16:59:47 2007 : Debug:     TLS_accept: SSLv3 write finished A 
Wed Jul  4 16:59:47 2007 : Debug:     TLS_accept: SSLv3 flush data 
Wed Jul  4 16:59:47 2007 : Debug:     (other): SSL negotiation finished successfully 
Wed Jul  4 16:59:47 2007 : Debug: SSL Connection Established 
Wed Jul  4 16:59:47 2007 : Debug:   eaptls_process returned 13 
Wed Jul  4 16:59:47 2007 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 3
Wed Jul  4 16:59:47 2007 : Debug:   modcall[authenticate]: module "eap" returns handled for request 3
Wed Jul  4 16:59:47 2007 : Debug: modcall: leaving group authenticate (returns handled) for request 3
Sending Access-Challenge of id 51 to 192.168.0.101 port 5001
	Framed-IP-Address = 255.255.255.254
	Framed-MTU = 576
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Framed-Compression = Van-Jacobson-TCP-IP
	EAP-Message = 0x0105003d15800000003314030100010116030100280817e0c979a1581256954dbd92eb185703224f29328669f70d77f4b1f115c60a36a6572ed53c7e4d
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xaf9772dd39f5fef5662a750d599a7173
Wed Jul  4 16:59:47 2007 : Debug: Finished request 3
Wed Jul  4 16:59:47 2007 : Debug: Going to the next request
Wed Jul  4 16:59:47 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 16:59:47 2007 : Debug: Waking up in 4 seconds...
rad_recv: Access-Request packet from host 192.168.0.101:5001, id=52, length=190
	User-Name = "windows"
	EAP-Message = 0x0205004715800000003d1703010038315e06986314921dfa4a6b6392bf76aece1d9b11dd11e7458b0af9a6cd1dfc3831088821584fc5c8022538952d178b18434d58ec558391cc
	Message-Authenticator = 0xe9f0eca8fad3c1fe3f3c01546c6858d4
	NAS-IP-Address = 192.168.0.101
	NAS-Identifier = "4500"
	NAS-Port = 268533761
	NAS-Port-Type = Ethernet
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Calling-Station-Id = "0017-a4e1-2c86"
	State = 0xaf9772dd39f5fef5662a750d599a7173
Wed Jul  4 16:59:48 2007 : Debug:   Processing the authorize section of radiusd.conf
Wed Jul  4 16:59:48 2007 : Debug: modcall: entering group authorize for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "chap" returns noop for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "mschap" returns noop for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 4
Wed Jul  4 16:59:48 2007 : Debug:     rlm_realm: No '@' in User-Name = "windows", looking up realm NULL
Wed Jul  4 16:59:48 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "suffix" returns noop for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap: EAP packet type response id 5 length 71
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "eap" returns updated for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 4
Wed Jul  4 16:59:48 2007 : Debug:     users: Matched entry DEFAULT at line 153
Wed Jul  4 16:59:48 2007 : Debug:     users: Matched entry DEFAULT at line 172
Wed Jul  4 16:59:48 2007 : Debug:     users: Matched entry DEFAULT at line 184
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "files" returns ok for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 4
Wed Jul  4 16:59:48 2007 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "pap" returns noop for request 4
Wed Jul  4 16:59:48 2007 : Debug: modcall: leaving group authorize (returns updated) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed Jul  4 16:59:48 2007 : Debug: auth: type "EAP"
Wed Jul  4 16:59:48 2007 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jul  4 16:59:48 2007 : Debug: modcall: entering group authenticate for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authenticate]: calling eap (rlm_eap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap: Request found, released from the list
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap: EAP/ttls
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap: processing type ttls
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap_ttls: Authenticate
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap_tls: processing TLS
Wed Jul  4 16:59:48 2007 : Debug: rlm_eap_tls:  Length Included
Wed Jul  4 16:59:48 2007 : Debug:   eaptls_verify returned 11 
Wed Jul  4 16:59:48 2007 : Debug:   eaptls_process returned 7 
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap_ttls: Session established.  Proceeding to decode tunneled attributes.
  TTLS tunnel data in 0000: 00 00 00 01 40 00 00 0f 77 69 6e 64 6f 77 73 00 
  TTLS tunnel data in 0010: 00 00 00 02 40 00 00 0f 77 69 6e 64 6f 77 73 00 
  TTLS: Got tunneled request
	User-Name = "windows"
	User-Password = "windows"
	FreeRADIUS-Proxied-To = 127.0.0.1
  TTLS: Sending tunneled request
	User-Name = "windows"
	User-Password = "windows"
	FreeRADIUS-Proxied-To = 127.0.0.1
Wed Jul  4 16:59:48 2007 : Debug:   Processing the authorize section of radiusd.conf
Wed Jul  4 16:59:48 2007 : Debug: modcall: entering group authorize for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "preprocess" returns ok for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling chap (rlm_chap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from chap (rlm_chap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "chap" returns noop for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling mschap (rlm_mschap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from mschap (rlm_mschap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "mschap" returns noop for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling suffix (rlm_realm) for request 4
Wed Jul  4 16:59:48 2007 : Debug:     rlm_realm: No '@' in User-Name = "windows", looking up realm NULL
Wed Jul  4 16:59:48 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from suffix (rlm_realm) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "suffix" returns noop for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling eap (rlm_eap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap: No EAP-Message, not doing EAP
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from eap (rlm_eap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "eap" returns noop for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling files (rlm_files) for request 4
Wed Jul  4 16:59:48 2007 : Debug:     users: Matched entry DEFAULT at line 153
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from files (rlm_files) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "files" returns ok for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: calling pap (rlm_pap) for request 4
Wed Jul  4 16:59:48 2007 : Debug: rlm_pap: WARNING! No "known good" password found for the user.  Authentication may fail because of this.
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authorize]: returned from pap (rlm_pap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authorize]: module "pap" returns noop for request 4
Wed Jul  4 16:59:48 2007 : Debug: modcall: leaving group authorize (returns ok) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   rad_check_password:  Found Auth-Type System
Wed Jul  4 16:59:48 2007 : Debug: auth: type "System"
Wed Jul  4 16:59:48 2007 : Debug:   Processing the authenticate section of radiusd.conf
Wed Jul  4 16:59:48 2007 : Debug: modcall: entering group authenticate for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authenticate]: calling unix (rlm_unix) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authenticate]: returned from unix (rlm_unix) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authenticate]: module "unix" returns ok for request 4
Wed Jul  4 16:59:48 2007 : Debug: modcall: leaving group authenticate (returns ok) for request 4
  TTLS: Got tunneled reply RADIUS code 2
Wed Jul  4 16:59:48 2007 : Debug:   TTLS: Got tunneled Access-Accept
Wed Jul  4 16:59:48 2007 : Debug:   rlm_eap: Freeing handler
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[authenticate]: returned from eap (rlm_eap) for request 4
Wed Jul  4 16:59:48 2007 : Debug:   modcall[authenticate]: module "eap" returns ok for request 4
Wed Jul  4 16:59:48 2007 : Debug: modcall: leaving group authenticate (returns ok) for request 4
Sending Access-Accept of id 52 to 192.168.0.101 port 5001
	Framed-IP-Address = 255.255.255.254
	Framed-MTU = 576
	Service-Type = Framed-User
	Framed-Protocol = PPP
	Framed-Compression = Van-Jacobson-TCP-IP
	MS-MPPE-Recv-Key = 0xfef30370af9456481e25da06b05e8791016870004a747ebffe1511441c1ef7ec
	MS-MPPE-Send-Key = 0x8719de99a610ee10bbb374c2e12a712cb9371dc8aceb2e2b10b3b60268d0bd52
	EAP-Message = 0x03050004
	Message-Authenticator = 0x00000000000000000000000000000000
	User-Name = "windows"
Wed Jul  4 16:59:48 2007 : Debug: Finished request 4
Wed Jul  4 16:59:48 2007 : Debug: Going to the next request
Wed Jul  4 16:59:48 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 16:59:48 2007 : Debug: Waking up in 3 seconds...
rad_recv: Accounting-Request packet from host 192.168.0.101:5001, id=81, length=102
	User-Name = "windows"
	NAS-Identifier = "4500"
	NAS-Port = 268533761
	NAS-Port-Type = Ethernet
	Calling-Station-Id = "0017-a4e1-2c86"
	Acct-Status-Type = Start
	Acct-Authentic = RADIUS
	Acct-Session-Id = "110706041659a"
	NAS-IP-Address = 192.168.0.101
	Event-Timestamp = "Jul  4 2007 18:59:28 CEST"
Wed Jul  4 16:59:48 2007 : Debug:   Processing the preacct section of radiusd.conf
Wed Jul  4 16:59:48 2007 : Debug: modcall: entering group preacct for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[preacct]: calling preprocess (rlm_preprocess) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[preacct]: returned from preprocess (rlm_preprocess) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modcall[preacct]: module "preprocess" returns noop for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[preacct]: calling acct_unique (rlm_acct_unique) for request 5
Wed Jul  4 16:59:48 2007 : Debug: rlm_acct_unique: Hashing 'NAS-Port = 268533761,Client-IP-Address = 192.168.0.101,NAS-IP-Address = 192.168.0.101,Acct-Session-Id = "110706041659a",User-Name = "windows"'
Wed Jul  4 16:59:48 2007 : Debug: rlm_acct_unique: Acct-Unique-Session-ID = "444a790794f6652e".
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[preacct]: returned from acct_unique (rlm_acct_unique) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modcall[preacct]: module "acct_unique" returns ok for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[preacct]: calling suffix (rlm_realm) for request 5
Wed Jul  4 16:59:48 2007 : Debug:     rlm_realm: No '@' in User-Name = "windows", looking up realm NULL
Wed Jul  4 16:59:48 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[preacct]: returned from suffix (rlm_realm) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modcall[preacct]: module "suffix" returns noop for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[preacct]: calling files (rlm_files) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[preacct]: returned from files (rlm_files) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modcall[preacct]: module "files" returns noop for request 5
Wed Jul  4 16:59:48 2007 : Debug: modcall: leaving group preacct (returns ok) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   Processing the accounting section of radiusd.conf
Wed Jul  4 16:59:48 2007 : Debug: modcall: entering group accounting for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[accounting]: calling detail (rlm_detail) for request 5
Wed Jul  4 16:59:48 2007 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.0.101/detail-20070704'
Wed Jul  4 16:59:48 2007 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.0.101/detail-20070704
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[accounting]: returned from detail (rlm_detail) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modcall[accounting]: module "detail" returns ok for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[accounting]: calling unix (rlm_unix) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[accounting]: returned from unix (rlm_unix) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modcall[accounting]: module "unix" returns ok for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[accounting]: calling radutmp (rlm_radutmp) for request 5
Wed Jul  4 16:59:48 2007 : Debug: radius_xlat:  '/var/log/freeradius/radutmp'
Wed Jul  4 16:59:48 2007 : Debug: radius_xlat:  'windows'
Wed Jul  4 16:59:48 2007 : Debug:   modsingle[accounting]: returned from radutmp (rlm_radutmp) for request 5
Wed Jul  4 16:59:48 2007 : Debug:   modcall[accounting]: module "radutmp" returns ok for request 5
Wed Jul  4 16:59:48 2007 : Debug: modcall: leaving group accounting (returns ok) for request 5
Sending Accounting-Response of id 81 to 192.168.0.101 port 5001
Wed Jul  4 16:59:48 2007 : Debug: Finished request 5
Wed Jul  4 16:59:48 2007 : Debug: Going to the next request
Wed Jul  4 16:59:48 2007 : Debug: Waking up in 3 seconds...
Wed Jul  4 16:59:51 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 16:59:51 2007 : Debug: Cleaning up request 0 ID 48 with timestamp 468bb5e1
Wed Jul  4 16:59:51 2007 : Debug: Cleaning up request 1 ID 49 with timestamp 468bb5e1
Wed Jul  4 16:59:51 2007 : Debug: Cleaning up request 5 ID 81 with timestamp 468bb5e4
Wed Jul  4 16:59:51 2007 : Debug: Waking up in 1 seconds...
Wed Jul  4 16:59:52 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 16:59:52 2007 : Debug: Cleaning up request 2 ID 50 with timestamp 468bb5e2
Wed Jul  4 16:59:52 2007 : Debug: Waking up in 1 seconds...
Wed Jul  4 16:59:53 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 16:59:53 2007 : Debug: Cleaning up request 3 ID 51 with timestamp 468bb5e3
Wed Jul  4 16:59:53 2007 : Debug: Waking up in 1 seconds...
Wed Jul  4 16:59:54 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 16:59:54 2007 : Debug: Cleaning up request 4 ID 52 with timestamp 468bb5e4
Wed Jul  4 16:59:54 2007 : Debug: Nothing to do.  Sleeping until we see a request.
rad_recv: Accounting-Request packet from host 192.168.0.101:5001, id=82, length=156
	User-Name = "windows"
	NAS-Identifier = "4500"
	NAS-Port = 268533761
	NAS-Port-Type = Ethernet
	Calling-Station-Id = "0017-a4e1-2c86"
	Acct-Status-Type = Stop
	Acct-Authentic = RADIUS
	Acct-Session-Id = "110706041659a"
	NAS-IP-Address = 192.168.0.101
	Event-Timestamp = "Jul  4 2007 19:00:28 CEST"
	Acct-Session-Time = 60
	Acct-Delay-Time = 0
	Acct-Input-Octets = 8915
	Acct-Input-Packets = 95
	Acct-Output-Octets = 8539
	Acct-Output-Packets = 117
	Acct-Input-Gigawords = 0
	Acct-Output-Gigawords = 0
	Acct-Terminate-Cause = Lost-Carrier
Wed Jul  4 17:00:48 2007 : Debug:   Processing the preacct section of radiusd.conf
Wed Jul  4 17:00:48 2007 : Debug: modcall: entering group preacct for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[preacct]: calling preprocess (rlm_preprocess) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[preacct]: returned from preprocess (rlm_preprocess) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modcall[preacct]: module "preprocess" returns noop for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[preacct]: calling acct_unique (rlm_acct_unique) for request 6
Wed Jul  4 17:00:48 2007 : Debug: rlm_acct_unique: Hashing 'NAS-Port = 268533761,Client-IP-Address = 192.168.0.101,NAS-IP-Address = 192.168.0.101,Acct-Session-Id = "110706041659a",User-Name = "windows"'
Wed Jul  4 17:00:48 2007 : Debug: rlm_acct_unique: Acct-Unique-Session-ID = "444a790794f6652e".
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[preacct]: returned from acct_unique (rlm_acct_unique) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modcall[preacct]: module "acct_unique" returns ok for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[preacct]: calling suffix (rlm_realm) for request 6
Wed Jul  4 17:00:48 2007 : Debug:     rlm_realm: No '@' in User-Name = "windows", looking up realm NULL
Wed Jul  4 17:00:48 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[preacct]: returned from suffix (rlm_realm) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modcall[preacct]: module "suffix" returns noop for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[preacct]: calling files (rlm_files) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[preacct]: returned from files (rlm_files) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modcall[preacct]: module "files" returns noop for request 6
Wed Jul  4 17:00:48 2007 : Debug: modcall: leaving group preacct (returns ok) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   Processing the accounting section of radiusd.conf
Wed Jul  4 17:00:48 2007 : Debug: modcall: entering group accounting for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[accounting]: calling detail (rlm_detail) for request 6
Wed Jul  4 17:00:48 2007 : Debug: radius_xlat:  '/var/log/freeradius/radacct/192.168.0.101/detail-20070704'
Wed Jul  4 17:00:48 2007 : Debug: rlm_detail: /var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /var/log/freeradius/radacct/192.168.0.101/detail-20070704
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[accounting]: returned from detail (rlm_detail) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modcall[accounting]: module "detail" returns ok for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[accounting]: calling unix (rlm_unix) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[accounting]: returned from unix (rlm_unix) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modcall[accounting]: module "unix" returns ok for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[accounting]: calling radutmp (rlm_radutmp) for request 6
Wed Jul  4 17:00:48 2007 : Debug: radius_xlat:  '/var/log/freeradius/radutmp'
Wed Jul  4 17:00:48 2007 : Debug: radius_xlat:  'windows'
Wed Jul  4 17:00:48 2007 : Debug:   modsingle[accounting]: returned from radutmp (rlm_radutmp) for request 6
Wed Jul  4 17:00:48 2007 : Debug:   modcall[accounting]: module "radutmp" returns ok for request 6
Wed Jul  4 17:00:48 2007 : Debug: modcall: leaving group accounting (returns ok) for request 6
Sending Accounting-Response of id 82 to 192.168.0.101 port 5001
Wed Jul  4 17:00:48 2007 : Debug: Finished request 6
Wed Jul  4 17:00:48 2007 : Debug: Going to the next request
Wed Jul  4 17:00:48 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 17:00:48 2007 : Debug: Waking up in 6 seconds...
Wed Jul  4 17:00:54 2007 : Debug: --- Walking the entire request list ---
Wed Jul  4 17:00:54 2007 : Debug: Cleaning up request 6 ID 82 with timestamp 468bb620
Wed Jul  4 17:00:54 2007 : Debug: Nothing to do.  Sleeping until we see a request.
