Problems with PEAP

pippo metallaro shyboy at hotmail.it
Thu May 10 15:05:58 CEST 2007


hi,

i use freeradius with eap -peap and MySQL...but the freeradius don't send an 
access-accept at the end of authentication  ...the server send an 
access-challenge,i don't know what's the problem...

i'use a hp 2650 switch client,and a win xp supplicant,

this is the the result of the debug mode..
Wed May  9 17:51:58 2007 : Info: Starting - reading configuration files ...
Wed May  9 17:51:58 2007 : Debug: reread_config:  reading radiusd.conf
Wed May  9 17:51:58 2007 : Debug: Config:   including file: 
/etc/freeradius/proxy.conf
Wed May  9 17:51:58 2007 : Debug: Config:   including file: 
/etc/freeradius/clients.conf
Wed May  9 17:51:58 2007 : Debug: Config:   including file: 
/etc/freeradius/snmp.conf
Wed May  9 17:51:58 2007 : Debug: Config:   including file: 
/etc/freeradius/eap.conf
Wed May  9 17:51:58 2007 : Debug: Config:   including file: 
/etc/freeradius/sql.conf
Wed May  9 17:51:58 2007 : Debug:  main: prefix = "/usr"
Wed May  9 17:51:58 2007 : Debug:  main: localstatedir = "/var"
Wed May  9 17:51:58 2007 : Debug:  main: logdir = "/var/log/freeradius"
Wed May  9 17:51:58 2007 : Debug:  main: libdir = "/usr/lib/freeradius"
Wed May  9 17:51:58 2007 : Debug:  main: radacctdir = 
"/var/log/freeradius/radacct"
Wed May  9 17:51:58 2007 : Debug:  main: hostname_lookups = no
Wed May  9 17:51:58 2007 : Debug:  main: max_request_time = 30
Wed May  9 17:51:58 2007 : Debug:  main: cleanup_delay = 5
Wed May  9 17:51:58 2007 : Debug:  main: max_requests = 1024
Wed May  9 17:51:58 2007 : Debug:  main: delete_blocked_requests = 0
Wed May  9 17:51:58 2007 : Debug:  main: port = 0
Wed May  9 17:51:58 2007 : Debug:  main: allow_core_dumps = no
Wed May  9 17:51:58 2007 : Debug:  main: log_stripped_names = no
Wed May  9 17:51:58 2007 : Debug:  main: log_file = 
"/var/log/freeradius/radius.log"
Wed May  9 17:51:58 2007 : Debug:  main: log_auth = no
Wed May  9 17:51:58 2007 : Debug:  main: log_auth_badpass = no
Wed May  9 17:51:58 2007 : Debug:  main: log_auth_goodpass = no
Wed May  9 17:51:58 2007 : Debug:  main: pidfile = 
"/var/run/freeradius/freeradius.pid"
Wed May  9 17:51:58 2007 : Debug:  main: bind_address = 192.168.0.1 IP 
address [192.168.0.1]
Wed May  9 17:51:58 2007 : Debug:  main: user = "freerad"
Wed May  9 17:51:58 2007 : Debug:  main: group = "freerad"
Wed May  9 17:51:58 2007 : Debug:  main: usercollide = no
Wed May  9 17:51:58 2007 : Debug:  main: lower_user = "no"
Wed May  9 17:51:58 2007 : Debug:  main: lower_pass = "no"
Wed May  9 17:51:58 2007 : Debug:  main: nospace_user = "no"
Wed May  9 17:51:58 2007 : Debug:  main: nospace_pass = "no"
Wed May  9 17:51:58 2007 : Debug:  main: checkrad = "/usr/sbin/checkrad"
Wed May  9 17:51:58 2007 : Debug:  main: proxy_requests = yes
Wed May  9 17:51:58 2007 : Debug:  proxy: retry_delay = 5
Wed May  9 17:51:58 2007 : Debug:  proxy: retry_count = 3
Wed May  9 17:51:58 2007 : Debug:  proxy: synchronous = no
Wed May  9 17:51:58 2007 : Debug:  proxy: default_fallback = yes
Wed May  9 17:51:58 2007 : Debug:  proxy: dead_time = 120
Wed May  9 17:51:58 2007 : Debug:  proxy: post_proxy_authorize = no
Wed May  9 17:51:58 2007 : Debug:  proxy: wake_all_if_all_dead = no
Wed May  9 17:51:58 2007 : Debug:  security: max_attributes = 200
Wed May  9 17:51:58 2007 : Debug:  security: reject_delay = 1
Wed May  9 17:51:58 2007 : Debug:  security: status_server = no
Wed May  9 17:51:58 2007 : Debug:  main: debug_level = 0
Wed May  9 17:51:58 2007 : Debug: read_config_files:  reading dictionary
Wed May  9 17:51:58 2007 : Debug: read_config_files:  reading naslist
Wed May  9 17:51:58 2007 : Info: Using deprecated naslist file.  Support for 
this will go away soon.
Wed May  9 17:51:58 2007 : Debug: read_config_files:  reading clients
Wed May  9 17:51:58 2007 : Debug: read_config_files:  reading realms
Wed May  9 17:51:58 2007 : Debug: radiusd:  entering modules setup
Wed May  9 17:51:58 2007 : Debug: Module: Library search path is 
/usr/lib/freeradius
Wed May  9 17:51:58 2007 : Debug: Module: Loaded exec
Wed May  9 17:51:58 2007 : Debug:  exec: wait = yes
Wed May  9 17:51:58 2007 : Debug:  exec: program = "(null)"
Wed May  9 17:51:58 2007 : Debug:  exec: input_pairs = "request"
Wed May  9 17:51:58 2007 : Debug:  exec: output_pairs = "(null)"
Wed May  9 17:51:58 2007 : Debug:  exec: packet_type = "(null)"
Wed May  9 17:51:58 2007 : Info: rlm_exec: Wait=yes but no output defined. 
Did you mean output=none?
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated exec (exec)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded expr
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated expr (expr)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded PAP
Wed May  9 17:51:58 2007 : Debug:  pap: encryption_scheme = "crypt"
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated pap (pap)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded CHAP
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated chap (chap)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded MS-CHAP
Wed May  9 17:51:58 2007 : Debug:  mschap: use_mppe = yes
Wed May  9 17:51:58 2007 : Debug:  mschap: require_encryption = yes
Wed May  9 17:51:58 2007 : Debug:  mschap: require_strong = yes
Wed May  9 17:51:58 2007 : Debug:  mschap: with_ntdomain_hack = no
Wed May  9 17:51:58 2007 : Debug:  mschap: passwd = "(null)"
Wed May  9 17:51:58 2007 : Debug:  mschap: ntlm_auth = "(null)"
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated mschap (mschap)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded eap
Wed May  9 17:51:58 2007 : Debug:  eap: default_eap_type = "peap"
Wed May  9 17:51:58 2007 : Debug:  eap: timer_expire = 60
Wed May  9 17:51:58 2007 : Debug:  eap: ignore_unknown_eap_types = no
Wed May  9 17:51:58 2007 : Debug:  eap: cisco_accounting_username_bug = no
Wed May  9 17:51:58 2007 : Debug: rlm_eap: Loaded and initialized type md5
Wed May  9 17:51:58 2007 : Debug: rlm_eap: Loaded and initialized type leap
Wed May  9 17:51:58 2007 : Debug:  tls: rsa_key_exchange = no
Wed May  9 17:51:58 2007 : Debug:  tls: dh_key_exchange = yes
Wed May  9 17:51:58 2007 : Debug:  tls: rsa_key_length = 512
Wed May  9 17:51:58 2007 : Debug:  tls: dh_key_length = 512
Wed May  9 17:51:58 2007 : Debug:  tls: verify_depth = 0
Wed May  9 17:51:58 2007 : Debug:  tls: CA_path = "(null)"
Wed May  9 17:51:58 2007 : Debug:  tls: pem_file_type = yes
Wed May  9 17:51:58 2007 : Debug:  tls: private_key_file = 
"/etc/freeradius/certs/cert-srv.pem"
Wed May  9 17:51:58 2007 : Debug:  tls: certificate_file = 
"/etc/freeradius/certs/cert-srv.pem"
Wed May  9 17:51:58 2007 : Debug:  tls: CA_file = 
"/etc/freeradius/certs/demoCA/cacert.pem"
Wed May  9 17:51:58 2007 : Debug:  tls: private_key_password = "whatever"
Wed May  9 17:51:58 2007 : Debug:  tls: dh_file = "/etc/freeradius/certs/dh"
Wed May  9 17:51:58 2007 : Debug:  tls: random_file = 
"/etc/freeradius/certs/random"
Wed May  9 17:51:58 2007 : Debug:  tls: fragment_size = 1024
Wed May  9 17:51:58 2007 : Debug:  tls: include_length = yes
Wed May  9 17:51:58 2007 : Debug:  tls: check_crl = no
Wed May  9 17:51:58 2007 : Debug:  tls: check_cert_cn = "(null)"
Wed May  9 17:51:58 2007 : Debug:  tls: cipher_list = "(null)"
Wed May  9 17:51:58 2007 : Debug:  tls: check_cert_issuer = "(null)"
Wed May  9 17:51:58 2007 : Info: rlm_eap_tls: Loading the certificate file 
as a chain
Wed May  9 17:51:58 2007 : Debug: rlm_eap: Loaded and initialized type tls
Wed May  9 17:51:58 2007 : Debug:  peap: default_eap_type = "mschapv2"
Wed May  9 17:51:58 2007 : Debug:  peap: copy_request_to_tunnel = no
Wed May  9 17:51:58 2007 : Debug:  peap: use_tunneled_reply = yes
Wed May  9 17:51:58 2007 : Debug:  peap: proxy_tunneled_request_as_eap = yes
Wed May  9 17:51:58 2007 : Debug: rlm_eap: Loaded and initialized type peap
Wed May  9 17:51:58 2007 : Debug:  mschapv2: with_ntdomain_hack = no
Wed May  9 17:51:58 2007 : Debug: rlm_eap: Loaded and initialized type 
mschapv2
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated eap (eap)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded preprocess
Wed May  9 17:51:58 2007 : Debug:  preprocess: huntgroups = 
"/etc/freeradius/huntgroups"
Wed May  9 17:51:58 2007 : Debug:  preprocess: hints = 
"/etc/freeradius/hints"
Wed May  9 17:51:58 2007 : Debug:  preprocess: with_ascend_hack = no
Wed May  9 17:51:58 2007 : Debug:  preprocess: ascend_channels_per_line = 23
Wed May  9 17:51:58 2007 : Debug:  preprocess: with_ntdomain_hack = no
Wed May  9 17:51:58 2007 : Debug:  preprocess: with_specialix_jetstream_hack 
= no
Wed May  9 17:51:58 2007 : Debug:  preprocess: with_cisco_vsa_hack = no
Wed May  9 17:51:58 2007 : Debug:  preprocess: with_alvarion_vsa_hack = no
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated preprocess 
(preprocess)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded realm
Wed May  9 17:51:58 2007 : Debug:  realm: format = "suffix"
Wed May  9 17:51:58 2007 : Debug:  realm: delimiter = "@"
Wed May  9 17:51:58 2007 : Debug:  realm: ignore_default = no
Wed May  9 17:51:58 2007 : Debug:  realm: ignore_null = no
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated realm (suffix)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded SQL
Wed May  9 17:51:58 2007 : Debug:  sql: driver = "rlm_sql_mysql"
Wed May  9 17:51:58 2007 : Debug:  sql: server = "localhost"
Wed May  9 17:51:58 2007 : Debug:  sql: port = ""
Wed May  9 17:51:58 2007 : Debug:  sql: login = "radius"
Wed May  9 17:51:58 2007 : Debug:  sql: password = "cisonline"
Wed May  9 17:51:58 2007 : Debug:  sql: radius_db = "radius"
Wed May  9 17:51:58 2007 : Debug:  sql: nas_table = "nas"
Wed May  9 17:51:58 2007 : Debug:  sql: sqltrace = no
Wed May  9 17:51:58 2007 : Debug:  sql: sqltracefile = 
"/var/log/freeradius/sqltrace.sql"
Wed May  9 17:51:58 2007 : Debug:  sql: readclients = no
Wed May  9 17:51:58 2007 : Debug:  sql: deletestalesessions = yes
Wed May  9 17:51:58 2007 : Debug:  sql: num_sql_socks = 5
Wed May  9 17:51:58 2007 : Debug:  sql: sql_user_name = "%{User-Name}"
Wed May  9 17:51:58 2007 : Debug:  sql: default_user_profile = ""
Wed May  9 17:51:58 2007 : Debug:  sql: query_on_not_found = no
Wed May  9 17:51:58 2007 : Debug:  sql: authorize_check_query = "SELECT id, 
UserName, Attribute, Value, op           FROM radcheck           WHERE 
Username = '%{SQL-User-Name}'           ORDER BY id"
Wed May  9 17:51:58 2007 : Debug:  sql: authorize_reply_query = "SELECT id, 
UserName, Attribute, Value, op           FROM radreply           WHERE 
Username = '%{SQL-User-Name}'           ORDER BY id"
Wed May  9 17:51:58 2007 : Debug:  sql: authorize_group_check_query = 
"SELECT 
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op 
  FROM radgroupcheck,usergroup WHERE usergroup.Username = '%{SQL-User-Name}' 
AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id"
Wed May  9 17:51:58 2007 : Debug:  sql: authorize_group_reply_query = 
"SELECT 
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op 
  FROM radgroupreply,usergroup WHERE usergroup.Username = '%{SQL-User-Name}' 
AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id"
Wed May  9 17:51:58 2007 : Debug:  sql: accounting_onoff_query = "UPDATE 
radacct SET AcctStopTime='%S', AcctSessionTime=unix_timestamp('%S') - 
unix_timestamp(AcctStartTime), AcctTerminateCause='%{Acct-Terminate-Cause}', 
AcctStopDelay = '%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND 
AcctStopTime=0 AND NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= 
'%S'"
Wed May  9 17:51:58 2007 : Debug:  sql: accounting_update_query = "UPDATE 
radacct           SET FramedIPAddress = '%{Framed-IP-Address}',           
AcctSessionTime = '%{Acct-Session-Time}',           AcctInputOctets = 
'%{Acct-Input-Octets}',           AcctOutputOctets = '%{Acct-Output-Octets}' 
           WHERE AcctSessionId = '%{Acct-Session-Id}'           AND UserName 
= '%{SQL-User-Name}'           AND NASIPAddress= '%{NAS-IP-Address}'"
Wed May  9 17:51:58 2007 : Debug:  sql: accounting_update_query_alt = 
"INSERT into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, 
NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctSessionTime, 
AcctAuthentic, ConnectInfo_start, AcctInputOctets, AcctOutputOctets, 
CalledStationId, CallingStationId, ServiceType, FramedProtocol, 
FramedIPAddress, AcctStartDelay) values('%{Acct-Session-Id}', 
'%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', 
'%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', 
DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} + %{Acct-Delay-Time:-0}) 
SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', 
'%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}', 
'%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', 
'%{Framed-IP-Address}', '0')"
Wed May  9 17:51:58 2007 : Debug:  sql: accounting_start_query = "INSERT 
into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, 
NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, 
AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, 
AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, 
ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) 
values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', 
'%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', 
'%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}', 
'', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', 
'%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', 
'%{Acct-Delay-Time}', '0')"
Wed May  9 17:51:58 2007 : Debug:  sql: accounting_start_query_alt = "UPDATE 
radacct SET AcctStartTime = '%S', AcctStartDelay = '%{Acct-Delay-Time}', 
ConnectInfo_start = '%{Connect-Info}' WHERE AcctSessionId = 
'%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND NASIPAddress = 
'%{NAS-IP-Address}'"
Wed May  9 17:51:58 2007 : Debug:  sql: accounting_stop_query = "UPDATE 
radacct SET AcctStopTime = '%S', AcctSessionTime = '%{Acct-Session-Time}', 
AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = 
'%{Acct-Output-Octets}', AcctTerminateCause = '%{Acct-Terminate-Cause}', 
AcctStopDelay = '%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' 
WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' 
AND NASIPAddress = '%{NAS-IP-Address}'"
Wed May  9 17:51:58 2007 : Debug:  sql: accounting_stop_query_alt = "INSERT 
into radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, 
NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, 
AcctAuthentic, ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, 
AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, 
ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay) 
values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', 
'%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', 
'%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} + 
%{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}', 
'%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}', 
'%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}', 
'%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', 
'%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')"
Wed May  9 17:51:58 2007 : Debug:  sql: group_membership_query = "SELECT 
GroupName FROM usergroup WHERE UserName='%{SQL-User-Name}'"
Wed May  9 17:51:58 2007 : Debug:  sql: connect_failure_retry_delay = 60
Wed May  9 17:51:58 2007 : Debug:  sql: simul_count_query = ""
Wed May  9 17:51:58 2007 : Debug:  sql: simul_verify_query = "SELECT 
RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, 
FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE 
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
Wed May  9 17:51:58 2007 : Debug:  sql: postauth_query = "INSERT into 
radpostauth (id, user, pass, reply, date) values ('', '%{User-Name}', 
'%{User-Password:-Chap-Password}', '%{reply:Packet-Type}', NOW())"
Wed May  9 17:51:58 2007 : Debug:  sql: safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Wed May  9 17:51:58 2007 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module 
rlm_sql_mysql) loaded and linked
Wed May  9 17:51:58 2007 : Info: rlm_sql (sql): Attempting to connect to 
radius at localhost:/radius
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): starting 0
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #0
Wed May  9 17:51:58 2007 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #0
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Connected new DB handle, #0
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): starting 1
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #1
Wed May  9 17:51:58 2007 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #1
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Connected new DB handle, #1
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): starting 2
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #2
Wed May  9 17:51:58 2007 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #2
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Connected new DB handle, #2
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): starting 3
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #3
Wed May  9 17:51:58 2007 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #3
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Connected new DB handle, #3
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): starting 4
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #4
Wed May  9 17:51:58 2007 : Info: rlm_sql_mysql: Starting connect to MySQL 
server for #4
Wed May  9 17:51:58 2007 : Debug: rlm_sql (sql): Connected new DB handle, #4
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated sql (sql)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded Acct-Unique-Session-Id
Wed May  9 17:51:58 2007 : Debug:  acct_unique: key = "User-Name, 
Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated acct_unique 
(acct_unique)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded detail
Wed May  9 17:51:58 2007 : Debug:  detail: detailfile = 
"/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Wed May  9 17:51:58 2007 : Debug:  detail: detailperm = 384
Wed May  9 17:51:58 2007 : Debug:  detail: dirperm = 493
Wed May  9 17:51:58 2007 : Debug:  detail: locking = no
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated detail (detail)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded System
Wed May  9 17:51:58 2007 : Debug:  unix: cache = no
Wed May  9 17:51:58 2007 : Debug:  unix: passwd = "(null)"
Wed May  9 17:51:58 2007 : Debug:  unix: shadow = "/etc/shadow"
Wed May  9 17:51:58 2007 : Debug:  unix: group = "(null)"
Wed May  9 17:51:58 2007 : Debug:  unix: radwtmp = 
"/var/log/freeradius/radwtmp"
Wed May  9 17:51:58 2007 : Debug:  unix: usegroup = no
Wed May  9 17:51:58 2007 : Debug:  unix: cache_reload = 600
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated unix (unix)
Wed May  9 17:51:58 2007 : Debug: Module: Loaded radutmp
Wed May  9 17:51:58 2007 : Debug:  radutmp: filename = 
"/var/log/freeradius/radutmp"
Wed May  9 17:51:58 2007 : Debug:  radutmp: username = "%{User-Name}"
Wed May  9 17:51:58 2007 : Debug:  radutmp: case_sensitive = yes
Wed May  9 17:51:58 2007 : Debug:  radutmp: check_with_nas = yes
Wed May  9 17:51:58 2007 : Debug:  radutmp: perm = 384
Wed May  9 17:51:58 2007 : Debug:  radutmp: callerid = yes
Wed May  9 17:51:58 2007 : Debug: Module: Instantiated radutmp (radutmp)
Wed May  9 17:51:58 2007 : Debug: Listening on authentication 
192.168.0.1:1812
Wed May  9 17:51:58 2007 : Debug: Listening on accounting 192.168.0.1:1813
Wed May  9 17:51:58 2007 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 192.168.0.254:1039, id=71, 
length=201
Framed-MTU = 1480
NAS-IP-Address = 172.17.1.10
NAS-Identifier = "CIS2650"
User-Name = "david"
Service-Type = Framed-User
Framed-Protocol = PPP
NAS-Port = 39
NAS-Port-Type = Ethernet
NAS-Port-Id = "39"
Called-Station-Id = "00-19-bb-6a-2d-80"
Calling-Station-Id = "00-11-25-d6-ab-1a"
Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3"
EAP-Message = 0x0201000c0170726174657369
Message-Authenticator = 0x0bce6099ad4417ee86a75d1549a6b2f2
Wed May  9 17:54:37 2007 : Debug:   Processing the authorize section of 
radiusd.conf
Wed May  9 17:54:37 2007 : Debug: modcall: entering group authorize for 
request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling preprocess 
(rlm_preprocess) for request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from 
preprocess (rlm_preprocess) for request 0
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "preprocess" 
returns ok for request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from chap 
(rlm_chap) for request 0
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "chap" 
returns noop for request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling mschap 
(rlm_mschap) for request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from 
mschap (rlm_mschap) for request 0
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "mschap" 
returns noop for request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling suffix 
(rlm_realm) for request 0
Wed May  9 17:54:37 2007 : Debug:     rlm_realm: No '@' in User-Name = 
"david", looking up realm NULL
Wed May  9 17:54:37 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from 
suffix (rlm_realm) for request 0
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "suffix" 
returns noop for request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 0
Wed May  9 17:54:37 2007 : Debug:   rlm_eap: EAP packet type response id 1 
length 12
Wed May  9 17:54:37 2007 : Debug:   rlm_eap: No EAP Start, assuming it's an 
on-going EAP conversation
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from eap 
(rlm_eap) for request 0
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "eap" returns 
updated for request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling sql 
(rlm_sql) for request 0
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'david'
Wed May  9 17:54:37 2007 : Debug: rlm_sql (sql): sql_set_user escaped user 
--> 'david'
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'SELECT id, UserName, 
Attribute, Value, op           FROM radcheck           WHERE Username = 
'david'           ORDER BY id'
Wed May  9 17:54:37 2007 : Debug: rlm_sql (sql): Reserving sql socket id: 4
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'SELECT 
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op 
  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'david' AND 
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'SELECT id, UserName, 
Attribute, Value, op           FROM radreply           WHERE Username = 
'david'           ORDER BY id'
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'SELECT 
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op 
  FROM radgroupreply,usergroup WHERE usergroup.Username = 'david' AND 
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
Wed May  9 17:54:37 2007 : Debug: rlm_sql (sql): Released sql socket id: 4
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from sql 
(rlm_sql) for request 0
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "sql" returns 
ok for request 0
Wed May  9 17:54:37 2007 : Debug: modcall: leaving group authorize (returns 
updated) for request 0
Wed May  9 17:54:37 2007 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed May  9 17:54:37 2007 : Debug: auth: type "EAP"
Wed May  9 17:54:37 2007 : Debug:   Processing the authenticate section of 
radiusd.conf
Wed May  9 17:54:37 2007 : Debug: modcall: entering group authenticate for 
request 0
Wed May  9 17:54:37 2007 : Debug:   modsingle[authenticate]: calling eap 
(rlm_eap) for request 0
Wed May  9 17:54:37 2007 : Debug:   rlm_eap: EAP Identity
Wed May  9 17:54:37 2007 : Debug:   rlm_eap: processing type tls
Wed May  9 17:54:37 2007 : Debug:   rlm_eap_tls: Initiate
Wed May  9 17:54:37 2007 : Debug:   rlm_eap_tls: Start returned 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authenticate]: returned from 
eap (rlm_eap) for request 0
Wed May  9 17:54:37 2007 : Debug:   modcall[authenticate]: module "eap" 
returns handled for request 0
Wed May  9 17:54:37 2007 : Debug: modcall: leaving group authenticate 
(returns handled) for request 0
Sending Access-Challenge of id 71 to 192.168.0.254 port 1039
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "1"
EAP-Message = 0x010200061920
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x1d29dc63e3727a27017d56d212ebbe51
Wed May  9 17:54:37 2007 : Debug: Finished request 0
Wed May  9 17:54:37 2007 : Debug: Going to the next request
Wed May  9 17:54:37 2007 : Debug: --- Walking the entire request list ---
Wed May  9 17:54:37 2007 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.254:1039, id=72, 
length=287
Framed-MTU = 1480
NAS-IP-Address = 172.17.1.10
NAS-Identifier = "CIS2650"
User-Name = "david"
Service-Type = Framed-User
Framed-Protocol = PPP
NAS-Port = 39
NAS-Port-Type = Ethernet
NAS-Port-Id = "39"
Called-Station-Id = "00-19-bb-6a-2d-80"
Calling-Station-Id = "00-11-25-d6-ab-1a"
Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3"
State = 0x1d29dc63e3727a27017d56d212ebbe51
EAP-Message = 
0x0202005019800000004616030100410100003d03014641eeacad5de1cf91cb82312b724ce969405f00152ecb9fe36317d9e794505500001600040005000a000900640062000300060013001200630100
Message-Authenticator = 0x848b664f7ebf5d0c45b92e1ea6dcbf29
Wed May  9 17:54:37 2007 : Debug:   Processing the authorize section of 
radiusd.conf
Wed May  9 17:54:37 2007 : Debug: modcall: entering group authorize for 
request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling preprocess 
(rlm_preprocess) for request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from 
preprocess (rlm_preprocess) for request 1
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "preprocess" 
returns ok for request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from chap 
(rlm_chap) for request 1
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "chap" 
returns noop for request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling mschap 
(rlm_mschap) for request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from 
mschap (rlm_mschap) for request 1
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "mschap" 
returns noop for request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling suffix 
(rlm_realm) for request 1
Wed May  9 17:54:37 2007 : Debug:     rlm_realm: No '@' in User-Name = 
"david", looking up realm NULL
Wed May  9 17:54:37 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from 
suffix (rlm_realm) for request 1
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "suffix" 
returns noop for request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 1
Wed May  9 17:54:37 2007 : Debug:   rlm_eap: EAP packet type response id 2 
length 80
Wed May  9 17:54:37 2007 : Debug:   rlm_eap: No EAP Start, assuming it's an 
on-going EAP conversation
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from eap 
(rlm_eap) for request 1
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "eap" returns 
updated for request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: calling sql 
(rlm_sql) for request 1
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'david'
Wed May  9 17:54:37 2007 : Debug: rlm_sql (sql): sql_set_user escaped user 
--> 'david'
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'SELECT id, UserName, 
Attribute, Value, op           FROM radcheck           WHERE Username = 
'david'           ORDER BY id'
Wed May  9 17:54:37 2007 : Debug: rlm_sql (sql): Reserving sql socket id: 3
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'SELECT 
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op 
  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'david' AND 
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'SELECT id, UserName, 
Attribute, Value, op           FROM radreply           WHERE Username = 
'david'           ORDER BY id'
Wed May  9 17:54:37 2007 : Debug: radius_xlat:  'SELECT 
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op 
  FROM radgroupreply,usergroup WHERE usergroup.Username = 'david' AND 
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
Wed May  9 17:54:37 2007 : Debug: rlm_sql (sql): Released sql socket id: 3
Wed May  9 17:54:37 2007 : Debug:   modsingle[authorize]: returned from sql 
(rlm_sql) for request 1
Wed May  9 17:54:37 2007 : Debug:   modcall[authorize]: module "sql" returns 
ok for request 1
Wed May  9 17:54:37 2007 : Debug: modcall: leaving group authorize (returns 
updated) for request 1
Wed May  9 17:54:37 2007 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed May  9 17:54:37 2007 : Debug: auth: type "EAP"
Wed May  9 17:54:37 2007 : Debug:   Processing the authenticate section of 
radiusd.conf
Wed May  9 17:54:37 2007 : Debug: modcall: entering group authenticate for 
request 1
Wed May  9 17:54:37 2007 : Debug:   modsingle[authenticate]: calling eap 
(rlm_eap) for request 1
Wed May  9 17:54:37 2007 : Debug:   rlm_eap: Request found, released from 
the list
Wed May  9 17:54:37 2007 : Debug:   rlm_eap: EAP/peap
Wed May  9 17:54:37 2007 : Debug:   rlm_eap: processing type peap
Wed May  9 17:54:37 2007 : Debug:   rlm_eap_peap: Authenticate
Wed May  9 17:54:37 2007 : Debug:   rlm_eap_tls: processing TLS
Wed May  9 17:54:37 2007 : Debug: rlm_eap_tls:  Length Included
Wed May  9 17:54:37 2007 : Debug:   eaptls_verify returned 11
Wed May  9 17:54:37 2007 : Debug:     (other): before/accept initialization
Wed May  9 17:54:37 2007 : Debug:     TLS_accept: before/accept 
initialization
Wed May  9 17:54:37 2007 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake 
[length 0041], ClientHello
Wed May  9 17:54:37 2007 : Debug:     TLS_accept: SSLv3 read client hello A
Wed May  9 17:54:37 2007 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake 
[length 004a], ServerHello
Wed May  9 17:54:37 2007 : Debug:     TLS_accept: SSLv3 write server hello A
Wed May  9 17:54:37 2007 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake 
[length 0346], Certificate
Wed May  9 17:54:37 2007 : Debug:     TLS_accept: SSLv3 write certificate A
Wed May  9 17:54:37 2007 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake 
[length 0004], ServerHelloDone
Wed May  9 17:54:37 2007 : Debug:     TLS_accept: SSLv3 write server done A
Wed May  9 17:54:37 2007 : Debug:     TLS_accept: SSLv3 flush data
Wed May  9 17:54:37 2007 : Error:     TLS_accept:error in SSLv3 read client 
certificate A
Wed May  9 17:54:37 2007 : Error: rlm_eap: SSL error 
error:00000000:lib(0):func(0):reason(0)
Wed May  9 17:54:37 2007 : Debug: In SSL Handshake Phase
Wed May  9 17:54:37 2007 : Debug: In SSL Accept mode
Wed May  9 17:54:37 2007 : Debug:   eaptls_process returned 13
Wed May  9 17:54:37 2007 : Debug:   rlm_eap_peap: EAPTLS_HANDLED
Wed May  9 17:54:37 2007 : Debug:   modsingle[authenticate]: returned from 
eap (rlm_eap) for request 1
Wed May  9 17:54:37 2007 : Debug:   modcall[authenticate]: module "eap" 
returns handled for request 1
Wed May  9 17:54:37 2007 : Debug: modcall: leaving group authenticate 
(returns handled) for request 1
Sending Access-Challenge of id 72 to 192.168.0.254 port 1039
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "1"
EAP-Message = 
0x010303a91900160301004a0200004603014641eebd4b0257f30568312508ce9d844da2ab8cdbc40e8bbfc011c7854f405e20d80a80e573f163f60573e9abfe1cf11719e3ebf6f8aa6607cac262017cc3521f00040016030103460b00034200033f00033c3082033830820220a003020102020102300d06092a864886f70d01010505003053310b3009060355040613024155311330110603550408130a536f6d652d53746174653121301f060355040a1318496e7465726e6574205769646769747320507479204c7464310c300a06035504031303636973301e170d3037303530333038303232355a170d3038303530323038303232355a3053310b30
EAP-Message = 
0x09060355040613024155311330110603550408130a536f6d652d53746174653121301f060355040a1318496e7465726e6574205769646769747320507479204c7464310c300a0603550403130363697330820122300d06092a864886f70d01010105000382010f003082010a0282010100be1f23b9bf021191c28df0d121a868f37aa0ed8650dfd3525c9bfd9782dd4528e7f670981ee608eb3c3b01334cff4532b4b59b3b132e71abdf2634bf00fc7234404f255291e3888816de19ea9c80b283a52d0f8cace67230d172f7ddcea6e0bd6793924b5d1c98c7cb80ea60f9a9b97757bf90420dcd25ddb79a500f4ef79f59dd0ae5b81fb6522f8d042a31
EAP-Message = 
0x6d2f0720a8dc00f73ad27bc737294cac8eeb7c914a7afa577c1532e34712f752a7a77e65e45350cf88a9d366f4d9bcc9ff4bb7611938a20f8534655fbfe0d205ef65eb408c91e3b1988d19144227aa8081ddcc94854619e0daadc64e0460d18ccaff05ac3163c3ca681aff1fcb62bab71a771a230203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d01010505000382010100339dc8986a5c60e942fcf5e76230fde8b3e75d73a8fc182512262617ec74b358d20452512e25bfc44d594cfaa100674207adb9f267d369ff7d5a6deb558b7cbd538aa5ccd4b44030be51acde4dc3ac940ec4c37335f277
EAP-Message = 
0x5246554e7c031fd501578b605daa683c51c0d38c12b48f088b2360a2bd6f4ae8edaf53617335befcb7e3eafe8c99e6adcd944b9e6da0a21acb056763d11b6e32a53d6bb3bb93d6dbfb8cc373f07f6efb2e9cf38ced2b04a43af28a00432d3bd936276b26a0f66540af127ed392a6cd83b89626ddcad0c090af2f239e05127baf8df9659dba0f0280415a9a6569c23dcbc22f3c2a2922826f56e5b1bd90f2a4c979ac2e52efb019932e16030100040e000000
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xc5018df96803d9ee44a6047b590c6057
Wed May  9 17:54:37 2007 : Debug: Finished request 1
Wed May  9 17:54:37 2007 : Debug: Going to the next request
Wed May  9 17:54:37 2007 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.0.254:1039, id=73, 
length=213
Framed-MTU = 1480
NAS-IP-Address = 172.17.1.10
NAS-Identifier = "CIS2650"
User-Name = "david"
Service-Type = Framed-User
Framed-Protocol = PPP
NAS-Port = 39
NAS-Port-Type = Ethernet
NAS-Port-Id = "39"
Called-Station-Id = "00-19-bb-6a-2d-80"
Calling-Station-Id = "00-11-25-d6-ab-1a"
Connect-Info = "CONNECT Ethernet 100Mbps Full duplex"
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3"
State = 0xc5018df96803d9ee44a6047b590c6057
EAP-Message = 0x020300061900
Message-Authenticator = 0x1ada415bcaa4a23684361400292abc59
Wed May  9 17:54:38 2007 : Debug:   Processing the authorize section of 
radiusd.conf
Wed May  9 17:54:38 2007 : Debug: modcall: entering group authorize for 
request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: calling preprocess 
(rlm_preprocess) for request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: returned from 
preprocess (rlm_preprocess) for request 2
Wed May  9 17:54:38 2007 : Debug:   modcall[authorize]: module "preprocess" 
returns ok for request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: returned from chap 
(rlm_chap) for request 2
Wed May  9 17:54:38 2007 : Debug:   modcall[authorize]: module "chap" 
returns noop for request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: calling mschap 
(rlm_mschap) for request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: returned from 
mschap (rlm_mschap) for request 2
Wed May  9 17:54:38 2007 : Debug:   modcall[authorize]: module "mschap" 
returns noop for request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: calling suffix 
(rlm_realm) for request 2
Wed May  9 17:54:38 2007 : Debug:     rlm_realm: No '@' in User-Name = 
"david", looking up realm NULL
Wed May  9 17:54:38 2007 : Debug:     rlm_realm: No such realm "NULL"
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: returned from 
suffix (rlm_realm) for request 2
Wed May  9 17:54:38 2007 : Debug:   modcall[authorize]: module "suffix" 
returns noop for request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 2
Wed May  9 17:54:38 2007 : Debug:   rlm_eap: EAP packet type response id 3 
length 6
Wed May  9 17:54:38 2007 : Debug:   rlm_eap: No EAP Start, assuming it's an 
on-going EAP conversation
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: returned from eap 
(rlm_eap) for request 2
Wed May  9 17:54:38 2007 : Debug:   modcall[authorize]: module "eap" returns 
updated for request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: calling sql 
(rlm_sql) for request 2
Wed May  9 17:54:38 2007 : Debug: radius_xlat:  'david'
Wed May  9 17:54:38 2007 : Debug: rlm_sql (sql): sql_set_user escaped user 
--> 'david'
Wed May  9 17:54:38 2007 : Debug: radius_xlat:  'SELECT id, UserName, 
Attribute, Value, op           FROM radcheck           WHERE Username = 
'david'           ORDER BY id'
Wed May  9 17:54:38 2007 : Debug: rlm_sql (sql): Reserving sql socket id: 2
Wed May  9 17:54:38 2007 : Debug: radius_xlat:  'SELECT 
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op 
  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'david' AND 
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
Wed May  9 17:54:38 2007 : Debug: radius_xlat:  'SELECT id, UserName, 
Attribute, Value, op           FROM radreply           WHERE Username = 
'david'           ORDER BY id'
Wed May  9 17:54:38 2007 : Debug: radius_xlat:  'SELECT 
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op 
  FROM radgroupreply,usergroup WHERE usergroup.Username = 'david' AND 
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
Wed May  9 17:54:38 2007 : Debug: rlm_sql (sql): Released sql socket id: 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authorize]: returned from sql 
(rlm_sql) for request 2
Wed May  9 17:54:38 2007 : Debug:   modcall[authorize]: module "sql" returns 
ok for request 2
Wed May  9 17:54:38 2007 : Debug: modcall: leaving group authorize (returns 
updated) for request 2
Wed May  9 17:54:38 2007 : Debug:   rad_check_password:  Found Auth-Type EAP
Wed May  9 17:54:38 2007 : Debug: auth: type "EAP"
Wed May  9 17:54:38 2007 : Debug:   Processing the authenticate section of 
radiusd.conf
Wed May  9 17:54:38 2007 : Debug: modcall: entering group authenticate for 
request 2
Wed May  9 17:54:38 2007 : Debug:   modsingle[authenticate]: calling eap 
(rlm_eap) for request 2
Wed May  9 17:54:38 2007 : Debug:   rlm_eap: Request found, released from 
the list
Wed May  9 17:54:38 2007 : Debug:   rlm_eap: EAP/peap
Wed May  9 17:54:38 2007 : Debug:   rlm_eap: processing type peap
Wed May  9 17:54:38 2007 : Debug:   rlm_eap_peap: Authenticate
Wed May  9 17:54:38 2007 : Debug:   rlm_eap_tls: processing TLS
Wed May  9 17:54:38 2007 : Debug: rlm_eap_tls: Received EAP-TLS ACK message
Wed May  9 17:54:38 2007 : Debug:   rlm_eap_tls: ack handshake fragment 
handler
Wed May  9 17:54:38 2007 : Debug:   eaptls_verify returned 1
Wed May  9 17:54:38 2007 : Debug:   eaptls_process returned 13
Wed May  9 17:54:38 2007 : Debug:   rlm_eap_peap: EAPTLS_HANDLED
Wed May  9 17:54:38 2007 : Debug:   modsingle[authenticate]: returned from 
eap (rlm_eap) for request 2
Wed May  9 17:54:38 2007 : Debug:   modcall[authenticate]: module "eap" 
returns handled for request 2
Wed May  9 17:54:38 2007 : Debug: modcall: leaving group authenticate 
(returns handled) for request 2
Sending Access-Challenge of id 73 to 192.168.0.254 port 1039
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "1"
EAP-Message = 0x010400061900
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xe7a8882c93b992e5d2c3b9eab695e62a
Wed May  9 17:54:38 2007 : Debug: Finished request 2
Wed May  9 17:54:38 2007 : Debug: Going to the next request
Wed May  9 17:54:38 2007 : Debug: --- Walking the entire request list ---
Wed May  9 17:54:38 2007 : Debug: Waking up in 5 seconds...
Wed May  9 17:54:43 2007 : Debug: --- Walking the entire request list ---
Wed May  9 17:54:43 2007 : Debug: Cleaning up request 0 ID 71 with timestamp 
4641eebd
Wed May  9 17:54:43 2007 : Debug: Cleaning up request 1 ID 72 with timestamp 
4641eebd
Wed May  9 17:54:43 2007 : Debug: Waking up in 1 seconds...
Wed May  9 17:54:44 2007 : Debug: --- Walking the entire request list ---
Wed May  9 17:54:44 2007 : Debug: Cleaning up request 2 ID 73 with timestamp 
4641eebe
Wed May  9 17:54:44 2007 : Debug: Nothing to do.  Sleeping until we see a 
request.

david

_________________________________________________________________
Personalizza la tua casella di posta con Windows Live Hotmail! 
http://imagine-windowslive.com/hotmail/default.aspx?locale=it#5




More information about the Freeradius-Users mailing list