New subject: exec-program-wait problem with freeradius 2.0.3

16 Apr 2008


      Here is a relevant part of the debug log:
...
Tue Apr 15 14:36:10 2008 : Info: FreeRADIUS Version 2.0.3, for host 
i686-pc-linux-gnu, built on Apr 11 2008 at 17:11:07
Tue Apr 15 14:36:10 2008 : Info: Copyright (C) 1999-2008 The 
FreeRADIUS server project and contributors.
Tue Apr 15 14:36:10 2008 : Info: There is NO warranty; not even for 
MERCHANTABILITY or FITNESS FOR A
Tue Apr 15 14:36:10 2008 : Info: PARTICULAR PURPOSE.
Tue Apr 15 14:36:10 2008 : Info: You may redistribute copies of 
FreeRADIUS under the terms of the
Tue Apr 15 14:36:10 2008 : Info: GNU General Public License.
Tue Apr 15 14:36:10 2008 : Info: Starting - reading configuration 
files ...
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/radiusd.conf
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/proxy.conf
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/clients.conf
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/snmp.conf
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/eap.conf
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/sql.conf
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/sql/mysql/dialup.conf
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/sql/mysql/counter.conf
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/policy.conf
Tue Apr 15 14:36:10 2008 : Debug: including files in directory 
/usr/local/freeradius203/etc/raddb/sites-enabled/
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/sites-enabled/default
Tue Apr 15 14:36:10 2008 : Debug: including configuration file 
/usr/local/freeradius203/etc/raddb/sites-enabled/inner-tunnel
Tue Apr 15 14:36:10 2008 : Debug: including dictionary file 
/usr/local/freeradius203/etc/raddb/dictionary
Tue Apr 15 14:36:10 2008 : Debug: main {
Tue Apr 15 14:36:10 2008 : Debug:     prefix = "/usr/local/freeradius203"
Tue Apr 15 14:36:10 2008 : Debug:     localstatedir = 
"/usr/local/freeradius203/var"
Tue Apr 15 14:36:10 2008 : Debug:     logdir = 
"/usr/local/freeradius203/var/log/radius"
Tue Apr 15 14:36:10 2008 : Debug:     libdir = 
"/usr/local/freeradius203/lib"
Tue Apr 15 14:36:10 2008 : Debug:     radacctdir = 
"/usr/local/freeradius203/var/log/radius/radacct"
Tue Apr 15 14:36:10 2008 : Debug:     hostname_lookups = no
Tue Apr 15 14:36:10 2008 : Debug:     max_request_time = 30
Tue Apr 15 14:36:10 2008 : Debug:     cleanup_delay = 5
Tue Apr 15 14:36:10 2008 : Debug:     max_requests = 1024
Tue Apr 15 14:36:10 2008 : Debug:     allow_core_dumps = no
Tue Apr 15 14:36:10 2008 : Debug:     pidfile = 
"/usr/local/freeradius203/var/run/radiusd/radiusd.pid"
Tue Apr 15 14:36:10 2008 : Debug:     user = "radiusd"
Tue Apr 15 14:36:10 2008 : Debug:     group = "radiusd"
Tue Apr 15 14:36:10 2008 : Debug:     checkrad = 
"/usr/local/freeradius203/sbin/checkrad"
Tue Apr 15 14:36:10 2008 : Debug:     debug_level = 0
Tue Apr 15 14:36:10 2008 : Debug:     proxy_requests = yes
Tue Apr 15 14:36:10 2008 : Debug:  security {
Tue Apr 15 14:36:10 2008 : Debug:     max_attributes = 200
Tue Apr 15 14:36:10 2008 : Debug:     reject_delay = 1
Tue Apr 15 14:36:10 2008 : Debug:     status_server = yes
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug: }
Tue Apr 15 14:36:10 2008 : Debug:  client localhost {
Tue Apr 15 14:36:10 2008 : Debug:     ipaddr = 127.0.0.1
Tue Apr 15 14:36:10 2008 : Debug:     require_message_authenticator = no
Tue Apr 15 14:36:10 2008 : Debug:     secret = "testing123"
Tue Apr 15 14:36:10 2008 : Debug:     nastype = "other"
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug:  client 192.168.1.0/24 {
Tue Apr 15 14:36:10 2008 : Debug:     require_message_authenticator = no
Tue Apr 15 14:36:10 2008 : Debug:     secret = "wlansenbel"
Tue Apr 15 14:36:10 2008 : Debug:     shortname = "wlan-sen"
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug: radiusd: #### Loading Realms and 
Home Servers ####
Tue Apr 15 14:36:10 2008 : Debug:  proxy server {
Tue Apr 15 14:36:10 2008 : Debug:     retry_delay = 5
Tue Apr 15 14:36:10 2008 : Debug:     retry_count = 3
Tue Apr 15 14:36:10 2008 : Debug:     default_fallback = no
Tue Apr 15 14:36:10 2008 : Debug:     dead_time = 120
Tue Apr 15 14:36:10 2008 : Debug:     wake_all_if_all_dead = no
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug:  home_server localhost {
Tue Apr 15 14:36:10 2008 : Debug:     ipaddr = 127.0.0.1
Tue Apr 15 14:36:10 2008 : Debug:     port = 1812
Tue Apr 15 14:36:10 2008 : Debug:     type = "auth"
Tue Apr 15 14:36:10 2008 : Debug:     secret = "testing123"
Tue Apr 15 14:36:10 2008 : Debug:     response_window = 20
Tue Apr 15 14:36:10 2008 : Debug:     max_outstanding = 65536
Tue Apr 15 14:36:10 2008 : Debug:     zombie_period = 40
Tue Apr 15 14:36:10 2008 : Debug:     status_check = "status-server"
Tue Apr 15 14:36:10 2008 : Debug:     ping_check = "none"
Tue Apr 15 14:36:10 2008 : Debug:     ping_interval = 30
Tue Apr 15 14:36:10 2008 : Debug:     check_interval = 30
Tue Apr 15 14:36:10 2008 : Debug:     num_answers_to_alive = 3
Tue Apr 15 14:36:10 2008 : Debug:     num_pings_to_alive = 3
Tue Apr 15 14:36:10 2008 : Debug:     revive_interval = 120
Tue Apr 15 14:36:10 2008 : Debug:     status_check_timeout = 4
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug:  home_server_pool my_auth_failover {
Tue Apr 15 14:36:10 2008 : Debug:     type = fail-over
Tue Apr 15 14:36:10 2008 : Debug:     home_server = localhost
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug:  realm example.com {
Tue Apr 15 14:36:10 2008 : Debug:     auth_pool = my_auth_failover
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug:  realm LOCAL {
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug: radiusd: #### Instantiating modules ####
Tue Apr 15 14:36:10 2008 : Debug:  instantiate {
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_exec, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_exec
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating exec
Tue Apr 15 14:36:10 2008 : Debug:   exec {
Tue Apr 15 14:36:10 2008 : Debug:     wait = yes
Tue Apr 15 14:36:10 2008 : Debug:     input_pairs = "request"
Tue Apr 15 14:36:10 2008 : Debug:     shell_escape = yes
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_expr, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_expr
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating expr
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_expiration, checking 
if it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_expiration
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating expiration
Tue Apr 15 14:36:10 2008 : Debug:   expiration {
Tue Apr 15 14:36:10 2008 : Debug:     reply-message = "Password Has 
Expired  "
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_logintime, checking 
if it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_logintime
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating logintime
Tue Apr 15 14:36:10 2008 : Debug:   logintime {
Tue Apr 15 14:36:10 2008 : Debug:     reply-message = "You are calling 
outside your allowed timespan  "
Tue Apr 15 14:36:10 2008 : Debug:     minimum-timeout = 60
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug: radiusd: #### Loading Virtual 
Servers ####
Tue Apr 15 14:36:10 2008 : Debug: server proxy-inner-tunnel {
Tue Apr 15 14:36:10 2008 : Debug:  modules {
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking authenticate {...} 
for more modules to load
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_eap, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_eap
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating eap
Tue Apr 15 14:36:10 2008 : Debug:   eap {
Tue Apr 15 14:36:10 2008 : Debug:     default_eap_type = "ttls"
Tue Apr 15 14:36:10 2008 : Debug:     timer_expire = 60
Tue Apr 15 14:36:10 2008 : Debug:     ignore_unknown_eap_types = no
Tue Apr 15 14:36:10 2008 : Debug:     cisco_accounting_username_bug = no
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to sub-module 
rlm_eap_md5
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating eap-md5
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to sub-module 
rlm_eap_leap
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating eap-leap
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to sub-module 
rlm_eap_gtc
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating eap-gtc
Tue Apr 15 14:36:10 2008 : Debug:    gtc {
Tue Apr 15 14:36:10 2008 : Debug:     challenge = "Password: "
Tue Apr 15 14:36:10 2008 : Debug:     auth_type = "PAP"
Tue Apr 15 14:36:10 2008 : Debug:    }
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to sub-module 
rlm_eap_tls
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating eap-tls
Tue Apr 15 14:36:10 2008 : Debug:    tls {
Tue Apr 15 14:36:10 2008 : Debug:     rsa_key_exchange = no
Tue Apr 15 14:36:10 2008 : Debug:     dh_key_exchange = yes
Tue Apr 15 14:36:10 2008 : Debug:     rsa_key_length = 512
Tue Apr 15 14:36:10 2008 : Debug:     dh_key_length = 512
Tue Apr 15 14:36:10 2008 : Debug:     verify_depth = 0
Tue Apr 15 14:36:10 2008 : Debug:     pem_file_type = yes
Tue Apr 15 14:36:10 2008 : Debug:     private_key_file = 
"/usr/local/freeradius203/etc/raddb/certs/cert-srv.pem"
Tue Apr 15 14:36:10 2008 : Debug:     certificate_file = 
"/usr/local/freeradius203/etc/raddb/certs/cert-srv.pem"
Tue Apr 15 14:36:10 2008 : Debug:     CA_file = 
"/usr/local/freeradius203/etc/raddb/certs/root.pem"
Tue Apr 15 14:36:10 2008 : Debug:     private_key_password = "XXXXX"
Tue Apr 15 14:36:10 2008 : Debug:     dh_file = 
"/usr/local/freeradius203/etc/raddb/certs/dh"
Tue Apr 15 14:36:10 2008 : Debug:     random_file = 
"/usr/local/freeradius203/etc/raddb/certs/random"
Tue Apr 15 14:36:10 2008 : Debug:     fragment_size = 1024
Tue Apr 15 14:36:10 2008 : Debug:     include_length = yes
Tue Apr 15 14:36:10 2008 : Debug:     check_crl = no
Tue Apr 15 14:36:10 2008 : Debug:     cipher_list = "DEFAULT"
Tue Apr 15 14:36:10 2008 : Debug:    }
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to sub-module 
rlm_eap_ttls
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating eap-ttls
Tue Apr 15 14:36:10 2008 : Debug:    ttls {
Tue Apr 15 14:36:10 2008 : Debug:     default_eap_type = "md5"
Tue Apr 15 14:36:10 2008 : Debug:     copy_request_to_tunnel = no
Tue Apr 15 14:36:10 2008 : Debug:     use_tunneled_reply = no
Tue Apr 15 14:36:10 2008 : Debug:     virtual_server = "inner-tunnel"
Tue Apr 15 14:36:10 2008 : Debug:    }
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to sub-module 
rlm_eap_peap
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating eap-peap
Tue Apr 15 14:36:10 2008 : Debug:    peap {
Tue Apr 15 14:36:10 2008 : Debug:     default_eap_type = "mschapv2"
Tue Apr 15 14:36:10 2008 : Debug:     copy_request_to_tunnel = no
Tue Apr 15 14:36:10 2008 : Debug:     use_tunneled_reply = no
Tue Apr 15 14:36:10 2008 : Debug:     proxy_tunneled_request_as_eap = yes
Tue Apr 15 14:36:10 2008 : Debug:     virtual_server = "inner-tunnel"
Tue Apr 15 14:36:10 2008 : Debug:    }
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to sub-module 
rlm_eap_mschapv2
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating eap-mschapv2
Tue Apr 15 14:36:10 2008 : Debug:    mschapv2 {
Tue Apr 15 14:36:10 2008 : Debug:     with_ntdomain_hack = no
Tue Apr 15 14:36:10 2008 : Debug:    }
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking authorize {...} 
for more modules to load
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking post-proxy {...} 
for more modules to load
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking post-auth {...} 
for more modules to load
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug: }
Tue Apr 15 14:36:10 2008 : Debug: server {
Tue Apr 15 14:36:10 2008 : Debug:  modules {
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking authenticate {...} 
for more modules to load
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_pap, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_pap
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating pap
Tue Apr 15 14:36:10 2008 : Debug:   pap {
Tue Apr 15 14:36:10 2008 : Debug:     encryption_scheme = "auto"
Tue Apr 15 14:36:10 2008 : Debug:     auto_header = no
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_chap, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_chap
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating chap
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_mschap, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_mschap
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating mschap
Tue Apr 15 14:36:10 2008 : Debug:   mschap {
Tue Apr 15 14:36:10 2008 : Debug:     use_mppe = yes
Tue Apr 15 14:36:10 2008 : Debug:     require_encryption = no
Tue Apr 15 14:36:10 2008 : Debug:     require_strong = no
Tue Apr 15 14:36:10 2008 : Debug:     with_ntdomain_hack = no
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_unix, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_unix
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating unix
Tue Apr 15 14:36:10 2008 : Debug:   unix {
Tue Apr 15 14:36:10 2008 : Debug:     radwtmp = 
"/usr/local/freeradius203/var/log/radius/radwtmp"
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking authorize {...} 
for more modules to load
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_preprocess, checking 
if it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_preprocess
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating preprocess
Tue Apr 15 14:36:10 2008 : Debug:   preprocess {
Tue Apr 15 14:36:10 2008 : Debug:     huntgroups = 
"/usr/local/freeradius203/etc/raddb/huntgroups"
Tue Apr 15 14:36:10 2008 : Debug:     hints = 
"/usr/local/freeradius203/etc/raddb/hints"
Tue Apr 15 14:36:10 2008 : Debug:     with_ascend_hack = no
Tue Apr 15 14:36:10 2008 : Debug:     ascend_channels_per_line = 23
Tue Apr 15 14:36:10 2008 : Debug:     with_ntdomain_hack = no
Tue Apr 15 14:36:10 2008 : Debug:     with_specialix_jetstream_hack = no
Tue Apr 15 14:36:10 2008 : Debug:     with_cisco_vsa_hack = yes
Tue Apr 15 14:36:10 2008 : Debug:     with_alvarion_vsa_hack = no
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_realm, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_realm
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating suffix
Tue Apr 15 14:36:10 2008 : Debug:   realm suffix {
Tue Apr 15 14:36:10 2008 : Debug:     format = "suffix"
Tue Apr 15 14:36:10 2008 : Debug:     delimiter = "@"
Tue Apr 15 14:36:10 2008 : Debug:     ignore_default = no
Tue Apr 15 14:36:10 2008 : Debug:     ignore_null = no
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_files, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_files
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating files
Tue Apr 15 14:36:10 2008 : Debug:   files {
Tue Apr 15 14:36:10 2008 : Debug:     usersfile = 
"/usr/local/freeradius203/etc/raddb/users"
Tue Apr 15 14:36:10 2008 : Debug:     acctusersfile = 
"/usr/local/freeradius203/etc/raddb/acct_users"
Tue Apr 15 14:36:10 2008 : Debug:     preproxy_usersfile = 
"/usr/local/freeradius203/etc/raddb/preproxy_users"
Tue Apr 15 14:36:10 2008 : Debug:     compat = "no"
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_sql, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_sql
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating sql
Tue Apr 15 14:36:10 2008 : Debug:   sql {
Tue Apr 15 14:36:10 2008 : Debug:     driver = "rlm_sql_mysql"
Tue Apr 15 14:36:10 2008 : Debug:     server = "localhost"
Tue Apr 15 14:36:10 2008 : Debug:     port = ""
Tue Apr 15 14:36:10 2008 : Debug:     login = "radius"
Tue Apr 15 14:36:10 2008 : Debug:     password = "XXXXX"
Tue Apr 15 14:36:10 2008 : Debug:     radius_db = "radius"
Tue Apr 15 14:36:10 2008 : Debug:     read_groups = yes
Tue Apr 15 14:36:10 2008 : Debug:     sqltrace = yes
Tue Apr 15 14:36:10 2008 : Debug:     sqltracefile = 
"/usr/local/freeradius203/var/log/radius/sqltrace.sql"
Tue Apr 15 14:36:10 2008 : Debug:     readclients = no
Tue Apr 15 14:36:10 2008 : Debug:     deletestalesessions = yes
Tue Apr 15 14:36:10 2008 : Debug:     num_sql_socks = 5
Tue Apr 15 14:36:10 2008 : Debug:     sql_user_name = "%{User-Name}"
Tue Apr 15 14:36:10 2008 : Debug:     default_user_profile = ""
Tue Apr 15 14:36:10 2008 : Debug:     nas_query = "SELECT id, nasname, 
shortname, type, secret FROM nas"
Tue Apr 15 14:36:10 2008 : Debug:     authorize_check_query = "SELECT 
id, username, attribute, value, op           FROM radcheck           
WHERE username = '%{SQL-User-Name}'           ORDER BY id"
Tue Apr 15 14:36:10 2008 : Debug:     authorize_reply_query = "SELECT 
id, username, attribute, value, op           FROM radreply           
WHERE username = '%{SQL-User-Name}'           ORDER BY id"
Tue Apr 15 14:36:10 2008 : Debug:     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"
Tue Apr 15 14:36:10 2008 : Debug:     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"
Tue Apr 15 14:36:10 2008 : Debug:     accounting_onoff_query = 
"          UPDATE radacct           SET              
acctstoptime       =  '%S',              acctsessiontime    =  
unix_timestamp('%S') -                                    
unix_timestamp(acctstarttime),              acctterminatecause =  
'%{Acct-Terminate-Cause}',              acctstopdelay      =  
%{%{Acct-Delay-Time}:-0}           WHERE acctsessiontime =  
0           AND acctstoptime      =  NULL           AND 
nasipaddress      =  '%{NAS-IP-Address}'           AND 
acctstarttime     <= '%S'"
Tue Apr 15 14:36:10 2008 : Debug:     accounting_update_query = 
"           UPDATE radacct           SET              framedipaddress 
= '%{Framed-IP-Address}',              acctsessiontime     = 
'%{Acct-Session-Time}',              acctinputoctets     = 
'%{%{Acct-Input-Gigawords}:-0}'  << 32 
|                                    
'%{%{Acct-Input-Octets}:-0}',              acctoutputoctets    = 
'%{%{Acct-Output-Gigawords}:-0}' << 32 
|                                    
'%{%{Acct-Output-Octets}:-0}'           WHERE acctsessionid = 
'%{Acct-Session-Id}'           AND username        = 
'%{SQL-User-Name}'           AND nasipaddress    = '%{NAS-IP-Address}'"
Tue Apr 15 14:36:10 2008 : Debug:     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,   
xascendsessionsvrkey)           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-Gigawords}:-0}' << 32 |              
'%{%{Acct-Input-Octets}:-0}',              
'%{%{Acct-Output-Gigawords}:-0}' << 32 |              
'%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}', 
'%{Calling-Station-Id}',              '%{Service-Type}', 
'%{Framed-Protocol}',              
'%{Framed-IP-Address}',              '0', '%{X-Ascend-Session-Svr-Key}')"
Tue Apr 15 14:36:10 2008 : Debug:     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,    xascendsessionsvrkey)           VALUES             
('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',              
'%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}', 
'%{NAS-Port}',              '%{NAS-Port-Type}', '%S', 
NULL,              '0', '%{Acct-Authentic}', 
'%{Connect-Info}',              '', '0', '0',              
'%{Called-Station-Id}', '%{Calling-Station-Id}', '',              
'%{Service-Type}', '%{Framed-Protocol}', 
'%{Framed-IP-Address}',              '%{%{Acct-Delay-Time}:-0}', '0', 
'%{X-Ascend-Session-Svr-Key}')"
Tue Apr 15 14:36:10 2008 : Debug:     accounting_start_query_alt = 
"           UPDATE radacct SET              acctstarttime     = 
'%S',              acctstartdelay    = 
'%{%{Acct-Delay-Time}:-0}',              connectinfo_start = 
'%{Connect-Info}'           WHERE acctsessionid  = 
'%{Acct-Session-Id}'           AND username         = 
'%{SQL-User-Name}'           AND nasipaddress     = '%{NAS-IP-Address}'"
Tue Apr 15 14:36:10 2008 : Debug:     accounting_stop_query = 
"           UPDATE radacct SET              acctstoptime       = 
'%S',              acctsessiontime    = 
'%{Acct-Session-Time}',              acctinputoctets    = 
'%{%{Acct-Input-Gigawords}:-0}' << 32 
|                                   
'%{%{Acct-Input-Octets}:-0}',              acctoutputoctets   = 
'%{%{Acct-Output-Gigawords}:-0}' << 32 
|                                   
'%{%{Acct-Output-Octets}:-0}',              acctterminatecause = 
'%{Acct-Terminate-Cause}',              acctstopdelay      = 
'%{%{Acct-Delay-Time}:-0}',              connectinfo_stop   = 
'%{Connect-Info}'           WHERE acctsessionid   = 
'%{Acct-Session-Id}'           AND username          = 
'%{SQL-User-Name}'           AND nasipaddress      = '%{NAS-IP-Address}'"
Tue Apr 15 14:36:10 2008 : Debug:     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-Gigawords}:-0}' << 32 
|              '%{%{Acct-Input-Octets}:-0}',              
'%{%{Acct-Output-Gigawords}:-0}' << 32 |              
'%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}', 
'%{Calling-Station-Id}',              
'%{Acct-Terminate-Cause}',              '%{Service-Type}', 
'%{Framed-Protocol}', '%{Framed-IP-Address}',              '0', 
'%{%{Acct-Delay-Time}:-0}')"
Tue Apr 15 14:36:10 2008 : Debug:     group_membership_query = "SELECT 
groupname           FROM usergroup           WHERE username = 
'%{SQL-User-Name}'           ORDER BY priority"
Tue Apr 15 14:36:10 2008 : Debug:     connect_failure_retry_delay = 60
Tue Apr 15 14:36:10 2008 : Debug:     simul_count_query = ""
Tue Apr 15 14:36:10 2008 : Debug:     simul_verify_query = "SELECT 
radacctid, acctsessionid, username,                                
nasipaddress, nasportid, 
framedipaddress,                                callingstationid, 
framedprotocol                                FROM 
radacct                                WHERE username = 
'%{SQL-User-Name}'                                AND acctstoptime = NULL"
Tue Apr 15 14:36:10 2008 : Debug:     postauth_query = "INSERT INTO 
radpostauth                           (username, pass, reply, 
authdate)                           VALUES (                           
'%{User-Name}',                           
'%{%{User-Password}:-%{Chap-Password}}',                           
'%{reply:Packet-Type}', '%S')"
Tue Apr 15 14:36:10 2008 : Debug:     safe-characters = 
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Info: rlm_sql (sql): Driver rlm_sql_mysql 
(module rlm_sql_mysql) loaded and linked
Tue Apr 15 14:36:10 2008 : Info: rlm_sql (sql): Attempting to connect 
to radius@localhost:/radius
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): starting 0
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #0
Tue Apr 15 14:36:10 2008 : Info: rlm_sql_mysql: Starting connect to 
MySQL server for #0
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Connected new DB 
handle, #0
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): starting 1
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #1
Tue Apr 15 14:36:10 2008 : Info: rlm_sql_mysql: Starting connect to 
MySQL server for #1
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Connected new DB 
handle, #1
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): starting 2
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #2
Tue Apr 15 14:36:10 2008 : Info: rlm_sql_mysql: Starting connect to 
MySQL server for #2
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Connected new DB 
handle, #2
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): starting 3
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #3
Tue Apr 15 14:36:10 2008 : Info: rlm_sql_mysql: Starting connect to 
MySQL server for #3
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Connected new DB 
handle, #3
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): starting 4
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Attempting to connect 
rlm_sql_mysql #4
Tue Apr 15 14:36:10 2008 : Info: rlm_sql_mysql: Starting connect to 
MySQL server for #4
Tue Apr 15 14:36:10 2008 : Debug: rlm_sql (sql): Connected new DB 
handle, #4
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking preacct {...} for 
more modules to load
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_acct_unique, 
checking if it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module 
rlm_acct_unique
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating acct_unique
Tue Apr 15 14:36:10 2008 : Debug:   acct_unique {
Tue Apr 15 14:36:10 2008 : Debug:     key = "User-Name, 
Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking accounting {...} 
for more modules to load
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_detail, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_detail
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating detail
Tue Apr 15 14:36:10 2008 : Debug:   detail {
Tue Apr 15 14:36:10 2008 : Debug:     detailfile = 
"/usr/local/freeradius203/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Tue Apr 15 14:36:10 2008 : Debug:     header = "%t"
Tue Apr 15 14:36:10 2008 : Debug:     detailperm = 384
Tue Apr 15 14:36:10 2008 : Debug:     dirperm = 493
Tue Apr 15 14:36:10 2008 : Debug:     locking = no
Tue Apr 15 14:36:10 2008 : Debug:     log_packet_header = no
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_radutmp, checking if 
it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module rlm_radutmp
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating radutmp
Tue Apr 15 14:36:10 2008 : Debug:   radutmp {
Tue Apr 15 14:36:10 2008 : Debug:     filename = 
"/usr/local/freeradius203/var/log/radius/radutmp"
Tue Apr 15 14:36:10 2008 : Debug:     username = "%{User-Name}"
Tue Apr 15 14:36:10 2008 : Debug:     case_sensitive = yes
Tue Apr 15 14:36:10 2008 : Debug:     check_with_nas = yes
Tue Apr 15 14:36:10 2008 : Debug:     perm = 384
Tue Apr 15 14:36:10 2008 : Debug:     callerid = yes
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:     (Loaded rlm_attr_filter, 
checking if it's valid)
Tue Apr 15 14:36:10 2008 : Debug:  Module: Linked to module 
rlm_attr_filter
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating 
attr_filter.accounting_response
Tue Apr 15 14:36:10 2008 : Debug:   attr_filter 
attr_filter.accounting_response {
Tue Apr 15 14:36:10 2008 : Debug:     attrsfile = 
"/usr/local/freeradius203/etc/raddb/attrs.accounting_response"
Tue Apr 15 14:36:10 2008 : Debug:     key = "%{User-Name}"
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking session {...} for 
more modules to load
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking post-proxy {...} 
for more modules to load
Tue Apr 15 14:36:10 2008 : Debug:  Module: Checking post-auth {...} 
for more modules to load
Tue Apr 15 14:36:10 2008 : Debug:  Module: Instantiating 
attr_filter.access_reject
Tue Apr 15 14:36:10 2008 : Debug:   attr_filter 
attr_filter.access_reject {
Tue Apr 15 14:36:10 2008 : Debug:     attrsfile = 
"/usr/local/freeradius203/etc/raddb/attrs.access_reject"
Tue Apr 15 14:36:10 2008 : Debug:     key = "%{User-Name}"
Tue Apr 15 14:36:10 2008 : Debug:   }
Tue Apr 15 14:36:10 2008 : Debug:  }
Tue Apr 15 14:36:10 2008 : Debug: }
Tue Apr 15 14:36:10 2008 : Debug: radiusd: #### Opening IP addresses 
and Ports ####
Tue Apr 15 14:36:10 2008 : Debug: listen {
Tue Apr 15 14:36:10 2008 : Debug:     type = "auth"
Tue Apr 15 14:36:10 2008 : Debug:     ipaddr = *
Tue Apr 15 14:36:10 2008 : Debug:     port = 0
Tue Apr 15 14:36:10 2008 : Debug: }
Tue Apr 15 14:36:10 2008 : Debug: listen {
Tue Apr 15 14:36:10 2008 : Debug:     type = "acct"
Tue Apr 15 14:36:10 2008 : Debug:     ipaddr = *
Tue Apr 15 14:36:10 2008 : Debug:     port = 0
Tue Apr 15 14:36:10 2008 : Debug: }
Tue Apr 15 14:36:10 2008 : Debug: Listening on authentication address 
* port 1812
Tue Apr 15 14:36:10 2008 : Debug: Listening on accounting address * 
port 1813
Tue Apr 15 14:36:10 2008 : Debug: Listening on proxy address * port 1814
Tue Apr 15 14:36:10 2008 : Debug: Ready to process requests.
    User-Name = "000d2885af3e"
    User-Password = "000d2885af3e"
    Called-Station-Id = "001e.4a06.0650"
    Calling-Station-Id = "000d.2885.af3e"
    Cisco-AVPair = "ssid=adsl"
    Service-Type = Login-User
    NAS-Port-Type = Wireless-802.11
    Cisco-NAS-Port = "737"
    NAS-Port = 737
    NAS-IP-Address = 192.168.1.110
    NAS-Identifier = "wlan_sen_10"
Tue Apr 15 14:36:27 2008 : Debug: +- entering group authorize
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling 
preprocess (rlm_preprocess) for request 0
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from preprocess (rlm_preprocess) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[preprocess] returns ok
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 0
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from chap (rlm_chap) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[chap] returns noop
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling 
mschap (rlm_mschap) for request 0
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from mschap (rlm_mschap) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[mschap] returns noop
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling 
suffix (rlm_realm) for request 0
Tue Apr 15 14:36:27 2008 : Debug:     rlm_realm: No '@' in User-Name = 
"000d2885af3e", looking up realm NULL
Tue Apr 15 14:36:27 2008 : Debug:     rlm_realm: No such realm "NULL"
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from suffix (rlm_realm) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[suffix] returns noop
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 0
Tue Apr 15 14:36:27 2008 : Debug:   rlm_eap: No EAP-Message, not doing EAP
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from eap (rlm_eap) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[eap] returns noop
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling unix 
(rlm_unix) for request 0
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from unix (rlm_unix) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[unix] returns notfound
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling 
files (rlm_files) for request 0
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from files (rlm_files) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[files] returns noop
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling sql 
(rlm_sql) for request 0
Tue Apr 15 14:36:27 2008 : Debug:     expand: %{User-Name} -> 000d2885af3e
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql (sql): sql_set_user escaped 
user --> '000d2885af3e'
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql (sql): Reserving sql socket 
id: 4
Tue Apr 15 14:36:27 2008 : Debug:     expand: SELECT id, username, 
attribute, value, op           FROM radcheck           WHERE username 
= '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, 
attribute, value, op           FROM radcheck           WHERE username 
= '000d2885af3e'           ORDER BY id
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql_mysql: query:  SELECT id, 
username, attribute, value, op           FROM radcheck           WHERE 
username = '000d2885af3e'           ORDER BY id
Tue Apr 15 14:36:27 2008 : Debug: WARNING: Found User-Password == "...".
Tue Apr 15 14:36:27 2008 : Debug: WARNING: Are you sure you don't mean 
Cleartext-Password?
Tue Apr 15 14:36:27 2008 : Debug: WARNING: See "man rlm_pap" for more 
information.
Tue Apr 15 14:36:27 2008 : Debug: WARNING: Found User-Password == "...".
Tue Apr 15 14:36:27 2008 : Debug: WARNING: Are you sure you don't mean 
Cleartext-Password?
Tue Apr 15 14:36:27 2008 : Debug: WARNING: See "man rlm_pap" for more 
information.
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql (sql): User found in 
radcheck table
Tue Apr 15 14:36:27 2008 : Debug:     expand: SELECT id, username, 
attribute, value, op           FROM radreply           WHERE username 
= '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, 
attribute, value, op           FROM radreply           WHERE username 
= '000d2885af3e'           ORDER BY id
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql_mysql: query:  SELECT id, 
username, attribute, value, op           FROM radreply           WHERE 
username = '000d2885af3e'           ORDER BY id
Tue Apr 15 14:36:27 2008 : Debug:     expand: SELECT 
groupname           FROM usergroup           WHERE username = 
'%{SQL-User-Name}'           ORDER BY priority -> SELECT 
groupname           FROM usergroup           WHERE username = 
'000d2885af3e'           ORDER BY priority
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql_mysql: query:  SELECT 
groupname           FROM usergroup           WHERE username = 
'000d2885af3e'           ORDER BY priority
Tue Apr 15 14:36:27 2008 : Debug:     expand: 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 -> SELECT 
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  
FROM radgroupcheck,usergroup WHERE usergroup.Username = '000d2885af3e' 
AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY 
radgroupcheck.id
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql_mysql: query:  SELECT 
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  
FROM radgroupcheck,usergroup WHERE usergroup.Username = '000d2885af3e' 
AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY 
radgroupcheck.id
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql (sql): User found in group wifi
Tue Apr 15 14:36:27 2008 : Debug:     expand: 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 -> SELECT 
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  
FROM radgroupreply,usergroup WHERE usergroup.Username = '000d2885af3e' 
AND usergroup.GroupName = radgroupreply.GroupName ORDER BY 
radgroupreply.id
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql_mysql: query:  SELECT 
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  
FROM radgroupreply,usergroup WHERE usergroup.Username = '000d2885af3e' 
AND usergroup.GroupName = radgroupreply.GroupName ORDER BY 
radgroupreply.id
Tue Apr 15 14:36:27 2008 : Debug: rlm_sql (sql): Released sql socket id: 4
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from sql (rlm_sql) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[sql] returns ok
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling 
expiration (rlm_expiration) for request 0
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from expiration (rlm_expiration) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[expiration] returns noop
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling 
logintime (rlm_logintime) for request 0
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from logintime (rlm_logintime) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[logintime] returns noop
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: calling pap 
(rlm_pap) for request 0
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authorize]: returned 
from pap (rlm_pap) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[pap] returns updated
Tue Apr 15 14:36:27 2008 : Debug:   rad_check_password:  Found Auth-Type
Tue Apr 15 14:36:27 2008 : Debug: 
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Apr 15 14:36:27 2008 : Debug: !!!    Replacing User-Password in 
config items with Cleartext-Password.     !!!
Tue Apr 15 14:36:27 2008 : Debug: 
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Apr 15 14:36:27 2008 : Debug: !!! Please update your configuration 
so that the "known good"               !!!
Tue Apr 15 14:36:27 2008 : Debug: !!! clear text password is in 
Cleartext-Password, and not in User-Password. !!!
Tue Apr 15 14:36:27 2008 : Debug: 
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Apr 15 14:36:27 2008 : Debug: auth: type "PAP"
Tue Apr 15 14:36:27 2008 : Debug: +- entering group PAP
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authenticate]: calling 
pap (rlm_pap) for request 0
Tue Apr 15 14:36:27 2008 : Debug: rlm_pap: login attempt with password 
"000d2885af3e"
Tue Apr 15 14:36:27 2008 : Debug: rlm_pap: Using clear text password 
"000d2885af3e"
Tue Apr 15 14:36:27 2008 : Debug: rlm_pap: User authenticated successfully
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[authenticate]: returned 
from pap (rlm_pap) for request 0
Tue Apr 15 14:36:27 2008 : Debug: ++[pap] returns ok
Tue Apr 15 14:36:27 2008 : Auth: Login OK: [000d2885af3e/000d2885af3e] 
(from client wlan-sen port 737 cli 000d.2885.af3e)
Tue Apr 15 14:36:27 2008 : Debug: +- entering group post-auth
Tue Apr 15 14:36:27 2008 : Debug:   modsingle[post-auth]: calling exec 
(rlm_exec) for request 0
Tue Apr 15 14:36:28 2008 : Debug: Exec-Program output:
Tue Apr 15 14:36:28 2008 : Debug: Exec-Program: returned: 0
Tue Apr 15 14:36:28 2008 : Debug:   modsingle[post-auth]: returned 
from exec (rlm_exec) for request 0
Tue Apr 15 14:36:28 2008 : Debug: ++[exec] returns noop
Tue Apr 15 14:36:28 2008 : Debug: Finished request 0.
Tue Apr 15 14:36:28 2008 : Debug: Going to the next request
Tue Apr 15 14:36:28 2008 : Debug: Waking up in 4.9 seconds.
    User-Name = "iti-adsl"
    Framed-MTU = 1400
    Called-Station-Id = "001e.4a06.0650"
    Calling-Station-Id = "000d.2885.af3e"
    Cisco-AVPair = "ssid=adsl"
    Service-Type = Login-User
    Message-Authenticator = 0x583a69bc84045763a4fe0ebfbfffad63
    EAP-Message = 0x0202000d016974692d6164736c
    NAS-Port-Type = Wireless-802.11
    Cisco-NAS-Port = "737"
    NAS-Port = 737
    NAS-IP-Address = 192.168.1.110
    NAS-Identifier = "wlan_sen_10"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authorize
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
preprocess (rlm_preprocess) for request 1
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from preprocess (rlm_preprocess) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[preprocess] returns ok
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 1
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from chap (rlm_chap) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[chap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
mschap (rlm_mschap) for request 1
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from mschap (rlm_mschap) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[mschap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
suffix (rlm_realm) for request 1
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No '@' in User-Name = 
"iti-adsl", looking up realm NULL
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No such realm "NULL"
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from suffix (rlm_realm) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[suffix] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 1
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP packet type response 
id 2 length 13
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: No EAP Start, assuming 
it's an on-going EAP conversation
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from eap (rlm_eap) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns updated
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling unix 
(rlm_unix) for request 1
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from unix (rlm_unix) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[unix] returns notfound
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
files (rlm_files) for request 1
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from files (rlm_files) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[files] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling sql 
(rlm_sql) for request 1
Tue Apr 15 14:36:31 2008 : Debug:     expand: %{User-Name} -> iti-adsl
Tue Apr 15 14:36:31 2008 : Debug: rlm_sql (sql): sql_set_user escaped 
user --> 'iti-adsl'
Tue Apr 15 14:36:31 2008 : Debug: rlm_sql (sql): Reserving sql socket 
id: 3
Tue Apr 15 14:36:31 2008 : Debug:     expand: SELECT id, username, 
attribute, value, op           FROM radcheck           WHERE username 
= '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, 
attribute, value, op           FROM radcheck           WHERE username 
= 'iti-adsl'           ORDER BY id
Tue Apr 15 14:36:31 2008 : Debug: rlm_sql_mysql: query:  SELECT id, 
username, attribute, value, op           FROM radcheck           WHERE 
username = 'iti-adsl'           ORDER BY id
Tue Apr 15 14:36:31 2008 : Debug:     expand: SELECT 
groupname           FROM usergroup           WHERE username = 
'%{SQL-User-Name}'           ORDER BY priority -> SELECT 
groupname           FROM usergroup           WHERE username = 
'iti-adsl'           ORDER BY priority
Tue Apr 15 14:36:31 2008 : Debug: rlm_sql_mysql: query:  SELECT 
groupname           FROM usergroup           WHERE username = 
'iti-adsl'           ORDER BY priority
Tue Apr 15 14:36:31 2008 : Debug: rlm_sql (sql): Released sql socket id: 3
Tue Apr 15 14:36:31 2008 : Debug: rlm_sql (sql): User iti-adsl not found
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from sql (rlm_sql) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[sql] returns notfound
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
expiration (rlm_expiration) for request 1
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from expiration (rlm_expiration) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[expiration] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
logintime (rlm_logintime) for request 1
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from logintime (rlm_logintime) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[logintime] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling pap 
(rlm_pap) for request 1
Tue Apr 15 14:36:31 2008 : Debug: rlm_pap: WARNING! No "known good" 
password found for the user.  Authentication may fail because of this.
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from pap (rlm_pap) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[pap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   rad_check_password:  Found 
Auth-Type EAP
Tue Apr 15 14:36:31 2008 : Debug: auth: type "EAP"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authenticate
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: calling 
eap (rlm_eap) for request 1
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP Identity
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: processing type tls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: Initiate
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: Start returned 1
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: returned 
from eap (rlm_eap) for request 1
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns handled
    EAP-Message = 0x010300061520
    Message-Authenticator = 0x00000000000000000000000000000000
    State = 0x34f6a43b34f5b18aae78afacd454dce9
Tue Apr 15 14:36:31 2008 : Debug: Finished request 1.
Tue Apr 15 14:36:31 2008 : Debug: Going to the next request
Tue Apr 15 14:36:31 2008 : Debug: Waking up in 1.7 seconds.
    User-Name = "iti-adsl"
    Framed-MTU = 1400
    Called-Station-Id = "001e.4a06.0650"
    Calling-Station-Id = "000d.2885.af3e"
    Cisco-AVPair = "ssid=adsl"
    Service-Type = Login-User
    Message-Authenticator = 0x2d3e53f084cf58829f768f2749f27a1a
    EAP-Message = 
0x0203003c158000000032160301002d010000290301c3a4f793f0ee849b7285f2b7734e75a6199e5ce283b2bb932c130c0d92d0936e000002000a0100
    NAS-Port-Type = Wireless-802.11
    Cisco-NAS-Port = "737"
    NAS-Port = 737
    State = 0x34f6a43b34f5b18aae78afacd454dce9
    NAS-IP-Address = 192.168.1.110
    NAS-Identifier = "wlan_sen_10"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authorize
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
preprocess (rlm_preprocess) for request 2
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from preprocess (rlm_preprocess) for request 2
Tue Apr 15 14:36:31 2008 : Debug: ++[preprocess] returns ok
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 2
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from chap (rlm_chap) for request 2
Tue Apr 15 14:36:31 2008 : Debug: ++[chap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
mschap (rlm_mschap) for request 2
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from mschap (rlm_mschap) for request 2
Tue Apr 15 14:36:31 2008 : Debug: ++[mschap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
suffix (rlm_realm) for request 2
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No '@' in User-Name = 
"iti-adsl", looking up realm NULL
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No such realm "NULL"
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from suffix (rlm_realm) for request 2
Tue Apr 15 14:36:31 2008 : Debug: ++[suffix] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 2
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP packet type response 
id 3 length 60
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: Continuing tunnel setup.
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from eap (rlm_eap) for request 2
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns ok
Tue Apr 15 14:36:31 2008 : Debug:   rad_check_password:  Found 
Auth-Type EAP
Tue Apr 15 14:36:31 2008 : Debug: auth: type "EAP"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authenticate
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: calling 
eap (rlm_eap) for request 2
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: Request found, released 
from the list
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP/ttls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: processing type ttls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_ttls: Authenticate
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: processing TLS
Tue Apr 15 14:36:31 2008 : Debug:   TLS Length 50
Tue Apr 15 14:36:31 2008 : Debug: rlm_eap_tls:  Length Included
Tue Apr 15 14:36:31 2008 : Debug:   eaptls_verify returned 11
Tue Apr 15 14:36:31 2008 : Debug:     (other): before/accept 
initialization
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: before/accept 
initialization
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake 
[length 002d], ClientHello  
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 read client 
hello A
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake 
[length 004a], ServerHello  
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 write server 
hello A
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake 
[length 05d0], Certificate  
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 write 
certificate A
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake 
[length 0004], ServerHelloDone  
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 write server 
done A
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 flush data
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: Need to read more 
data: SSLv3 read client certificate A
Tue Apr 15 14:36:31 2008 : Debug: In SSL Handshake Phase
Tue Apr 15 14:36:31 2008 : Debug: In SSL Accept mode  
Tue Apr 15 14:36:31 2008 : Debug:   eaptls_process returned 13
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: returned 
from eap (rlm_eap) for request 2
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns handled
    EAP-Message = 
0x0104040015c00000062d160301004a0200004603014804a14f03405808f80efd689b16fd48c086f6998ccb91e7ce31c66d6bebc8b62092f827b2e4dfb176a999d0ceff8c436ed65acf3d35e7b1bcdf27f3591336b0d1000a0016030105d00b0005cc0005c90002913082028d308201f6a0030201020209009b4c355fc730b340300d06092a864886f70d0101050500306e310b3009060355040613024245310a3008060355040813012d31173015060355040a130e42656c6769616e2053656e617465310c300a060355040b1303494354310f300d0603550403130653454e42454c311b301906092a864886f70d010901160c65774073656e6174652e
    EAP-Message = 
0x6265301e170d3038303430343132303030385a170d3039303430343132303030385a308189310b3009060355040613024245310a3008060355040813012d3111300f060355040713084272757373656c7331173015060355040a130e42656c6769616e2053656e617465310c300a060355040b1303494354311730150603550403130e776966692e73656e6174652e6265311b301906092a864886f70d010901160c65774073656e6174652e626530819f300d06092a864886f70d010101050003818d0030818902818100f468ade3112865f474ffaf100681888d5884c3820307cccddbd320f6cde2ae8d6c0e65d7943ac29a379025237c9a94de1fce
    EAP-Message = 
0xef6996f4601060f1e511309ece0c6439a2fe733b287ea222a600d9702a91460fb5e7bc9ec0745654955a8e23bbd43b429fd9ca517edee32c6f959f1afe468020b98dacb27489aea9ee5109bbc18d0203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d01010505000381810094b832d0e01efc00262169ec6f9fac129c2134822e878b7205359774d793a1ef52e891875bedafe868037724774bb3202b2e606b318f67cd3c19275f96037219aaa469f84be30c121f46c3568863aebf970d4460891a417c09b4a58fe24408058dac50f9260f3a65dec2afedfc3bb17645b8689f16614e7d8fee1150cf13
    EAP-Message = 
0x24280003323082032e30820297a0030201020209009b4c355fc730b33e300d06092a864886f70d0101050500306e310b3009060355040613024245310a3008060355040813012d31173015060355040a130e42656c6769616e2053656e617465310c300a060355040b1303494354310f300d0603550403130653454e42454c311b301906092a864886f70d010901160c65774073656e6174652e6265301e170d3038303430343131353931355a170d3132303430333131353931355a306e310b3009060355040613024245310a3008060355040813012d31173015060355040a130e42656c6769616e2053656e617465310c300a060355040b13034943
    EAP-Message = 0x54310f300d06035504031306
    Message-Authenticator = 0x00000000000000000000000000000000
    State = 0x34f6a43b35f2b18aae78afacd454dce9
Tue Apr 15 14:36:31 2008 : Debug: Finished request 2.
Tue Apr 15 14:36:31 2008 : Debug: Going to the next request
Tue Apr 15 14:36:31 2008 : Debug: Waking up in 1.7 seconds.
    User-Name = "iti-adsl"
    Framed-MTU = 1400
    Called-Station-Id = "001e.4a06.0650"
    Calling-Station-Id = "000d.2885.af3e"
    Cisco-AVPair = "ssid=adsl"
    Service-Type = Login-User
    Message-Authenticator = 0xc78aa2bce8b1b4622c908f338417907c
    EAP-Message = 0x020400061500
    NAS-Port-Type = Wireless-802.11
    Cisco-NAS-Port = "737"
    NAS-Port = 737
    State = 0x34f6a43b35f2b18aae78afacd454dce9
    NAS-IP-Address = 192.168.1.110
    NAS-Identifier = "wlan_sen_10"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authorize
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
preprocess (rlm_preprocess) for request 3
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from preprocess (rlm_preprocess) for request 3
Tue Apr 15 14:36:31 2008 : Debug: ++[preprocess] returns ok
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 3
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from chap (rlm_chap) for request 3
Tue Apr 15 14:36:31 2008 : Debug: ++[chap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
mschap (rlm_mschap) for request 3
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from mschap (rlm_mschap) for request 3
Tue Apr 15 14:36:31 2008 : Debug: ++[mschap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
suffix (rlm_realm) for request 3
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No '@' in User-Name = 
"iti-adsl", looking up realm NULL
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No such realm "NULL"
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from suffix (rlm_realm) for request 3
Tue Apr 15 14:36:31 2008 : Debug: ++[suffix] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 3
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP packet type response 
id 4 length 6
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: Continuing tunnel setup.
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from eap (rlm_eap) for request 3
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns ok
Tue Apr 15 14:36:31 2008 : Debug:   rad_check_password:  Found 
Auth-Type EAP
Tue Apr 15 14:36:31 2008 : Debug: auth: type "EAP"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authenticate
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: calling 
eap (rlm_eap) for request 3
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: Request found, released 
from the list
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP/ttls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: processing type ttls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_ttls: Authenticate
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: processing TLS
Tue Apr 15 14:36:31 2008 : Debug: rlm_eap_tls: Received EAP-TLS ACK 
message
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: ack handshake 
fragment handler
Tue Apr 15 14:36:31 2008 : Debug:   eaptls_verify returned 1
Tue Apr 15 14:36:31 2008 : Debug:   eaptls_process returned 13
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: returned 
from eap (rlm_eap) for request 3
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns handled
    EAP-Message = 
0x0105024115800000062d53454e42454c311b301906092a864886f70d010901160c65774073656e6174652e626530819f300d06092a864886f70d010101050003818d0030818902818100bf322c0fe8f317e2de850810f2dcfd2a172d16d4d3ef14a2c49b6bba3ba6d8d13d9b51336b6915d1c28e3e59e48f9d73896b1c66f67c80856d61b2db16706f1f3d91890a796c21137acd951f0763b1052b3955cd8902d230cf25dde50cc9f0d202fcd9834f9f1ba64fd2af92ade9fdcc66d089c8930554ee3da2092878463b330203010001a381d33081d0301d0603551d0e041604143253b8ff54d50cb877865c7818f38eaafbd60fb33081a00603551d2304
    EAP-Message = 
0x819830819580143253b8ff54d50cb877865c7818f38eaafbd60fb3a172a470306e310b3009060355040613024245310a3008060355040813012d31173015060355040a130e42656c6769616e2053656e617465310c300a060355040b1303494354310f300d0603550403130653454e42454c311b301906092a864886f70d010901160c65774073656e6174652e62658209009b4c355fc730b33e300c0603551d13040530030101ff300d06092a864886f70d010105050003818100a5fb290f87afd03e46ffac99dc526494bd08f9cab64018884f55cf7ec81445adf3667aaee0b0332844ed0504846b440cb6a3507dfc767491b99324c3801aec16f74d
    EAP-Message = 
0x16e9fad21aae6de23e698ede300a9e917cb83410fd2390b21c3ef3246aeb0cf517bfdce3c658944c66b4c671ce052ed12e051de9b8e50f1693fa1d35c93e16030100040e000000
    Message-Authenticator = 0x00000000000000000000000000000000
    State = 0x34f6a43b36f3b18aae78afacd454dce9
Tue Apr 15 14:36:31 2008 : Debug: Finished request 3.
Tue Apr 15 14:36:31 2008 : Debug: Going to the next request
Tue Apr 15 14:36:31 2008 : Debug: Waking up in 1.7 seconds.
    User-Name = "iti-adsl"
    Framed-MTU = 1400
    Called-Station-Id = "001e.4a06.0650"
    Calling-Station-Id = "000d.2885.af3e"
    Cisco-AVPair = "ssid=adsl"
    Service-Type = Login-User
    Message-Authenticator = 0xdedcf150fd3e3faa5c45383dcf851109
    EAP-Message = 
0x020500c81580000000be1603010086100000820080a783e9c770fcf3ae5e2510476beeaeb3e6a35f32046a627b0f508bd73ba3555335ed4205bd2a2b7de82f1b872f2dffcccef08341736d1e13a23669dcc2e6919c2f01cb068fbd72ea0eb20879632b10e4c8fa066443ae88ef9f224d998acd6001d84a8735ae27b7d515458215dd6eeba284816c02a18f4e4d30b5a853a4fa435d1403010001011603010028c2ff7430b77a3e79ed73b16ce555f749949bc5ff6bd5e59cc4746db0e8d75821e9b71831d6644977
    NAS-Port-Type = Wireless-802.11
    Cisco-NAS-Port = "737"
    NAS-Port = 737
    State = 0x34f6a43b36f3b18aae78afacd454dce9
    NAS-IP-Address = 192.168.1.110
    NAS-Identifier = "wlan_sen_10"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authorize
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
preprocess (rlm_preprocess) for request 4
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from preprocess (rlm_preprocess) for request 4
Tue Apr 15 14:36:31 2008 : Debug: ++[preprocess] returns ok
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 4
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from chap (rlm_chap) for request 4
Tue Apr 15 14:36:31 2008 : Debug: ++[chap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
mschap (rlm_mschap) for request 4
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from mschap (rlm_mschap) for request 4
Tue Apr 15 14:36:31 2008 : Debug: ++[mschap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
suffix (rlm_realm) for request 4
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No '@' in User-Name = 
"iti-adsl", looking up realm NULL
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No such realm "NULL"
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from suffix (rlm_realm) for request 4
Tue Apr 15 14:36:31 2008 : Debug: ++[suffix] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 4
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP packet type response 
id 5 length 200
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: Continuing tunnel setup.
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from eap (rlm_eap) for request 4
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns ok
Tue Apr 15 14:36:31 2008 : Debug:   rad_check_password:  Found 
Auth-Type EAP
Tue Apr 15 14:36:31 2008 : Debug: auth: type "EAP"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authenticate
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: calling 
eap (rlm_eap) for request 4
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: Request found, released 
from the list
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP/ttls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: processing type ttls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_ttls: Authenticate
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: processing TLS
Tue Apr 15 14:36:31 2008 : Debug:   TLS Length 190
Tue Apr 15 14:36:31 2008 : Debug: rlm_eap_tls:  Length Included
Tue Apr 15 14:36:31 2008 : Debug:   eaptls_verify returned 11
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake 
[length 0086], ClientKeyExchange  
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 read client 
key exchange A
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 
ChangeCipherSpec [length 0001]  
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake 
[length 0010], Finished  
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 read finished A
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 
ChangeCipherSpec [length 0001]  
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 write change 
cipher spec A
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake 
[length 0010], Finished  
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 write finished A
Tue Apr 15 14:36:31 2008 : Debug:     TLS_accept: SSLv3 flush data
Tue Apr 15 14:36:31 2008 : Debug:     (other): SSL negotiation 
finished successfully
Tue Apr 15 14:36:31 2008 : Debug: SSL Connection Established
Tue Apr 15 14:36:31 2008 : Debug:   eaptls_process returned 13
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: returned 
from eap (rlm_eap) for request 4
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns handled
    EAP-Message = 
0x0106003d1580000000331403010001011603010028d3454caad7ea42704da45ef294919c050d0ca2c1132b0c86b4e4a5495a938842ee1fac9833c1c356
    Message-Authenticator = 0x00000000000000000000000000000000
    State = 0x34f6a43b37f0b18aae78afacd454dce9
Tue Apr 15 14:36:31 2008 : Debug: Finished request 4.
Tue Apr 15 14:36:31 2008 : Debug: Going to the next request
Tue Apr 15 14:36:31 2008 : Debug: Waking up in 1.5 seconds.
    User-Name = "iti-adsl"
    Framed-MTU = 1400
    Called-Station-Id = "001e.4a06.0650"
    Calling-Station-Id = "000d.2885.af3e"
    Cisco-AVPair = "ssid=adsl"
    Service-Type = Login-User
    Message-Authenticator = 0xff5184884f621ac8b13f7ca8d6537687
    EAP-Message = 
0x0206004715800000003d1703010038e4e1c576ac5b647fe37888f18217d1fcefbb6e64bd33f8299a3dd4a688ca0749c876db7581411c2be08cfdddea6835ceed4ec47f9bfb0efc
    NAS-Port-Type = Wireless-802.11
    Cisco-NAS-Port = "737"
    NAS-Port = 737
    State = 0x34f6a43b37f0b18aae78afacd454dce9
    NAS-IP-Address = 192.168.1.110
    NAS-Identifier = "wlan_sen_10"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authorize
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
preprocess (rlm_preprocess) for request 5
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from preprocess (rlm_preprocess) for request 5
Tue Apr 15 14:36:31 2008 : Debug: ++[preprocess] returns ok
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 5
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from chap (rlm_chap) for request 5
Tue Apr 15 14:36:31 2008 : Debug: ++[chap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
mschap (rlm_mschap) for request 5
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from mschap (rlm_mschap) for request 5
Tue Apr 15 14:36:31 2008 : Debug: ++[mschap] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling 
suffix (rlm_realm) for request 5
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No '@' in User-Name = 
"iti-adsl", looking up realm NULL
Tue Apr 15 14:36:31 2008 : Debug:     rlm_realm: No such realm "NULL"
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from suffix (rlm_realm) for request 5
Tue Apr 15 14:36:31 2008 : Debug: ++[suffix] returns noop
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 5
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP packet type response 
id 6 length 71
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: Continuing tunnel setup.
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authorize]: returned 
from eap (rlm_eap) for request 5
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns ok
Tue Apr 15 14:36:31 2008 : Debug:   rad_check_password:  Found 
Auth-Type EAP
Tue Apr 15 14:36:31 2008 : Debug: auth: type "EAP"
Tue Apr 15 14:36:31 2008 : Debug: +- entering group authenticate
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: calling 
eap (rlm_eap) for request 5
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: Request found, released 
from the list
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: EAP/ttls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: processing type ttls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_ttls: Authenticate
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_tls: processing TLS
Tue Apr 15 14:36:31 2008 : Debug:   TLS Length 61
Tue Apr 15 14:36:31 2008 : Debug: rlm_eap_tls:  Length Included
Tue Apr 15 14:36:31 2008 : Debug:   eaptls_verify returned 11
Tue Apr 15 14:36:31 2008 : Debug:   eaptls_process returned 7
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap_ttls: Session 
established.  Proceeding to decode tunneled attributes.
Tue Apr 15 14:36:31 2008 : Debug: auth: No authenticate method 
(Auth-Type) configuration found for the request: Rejecting the user
Tue Apr 15 14:36:31 2008 : Debug: auth: Failed to validate the user.
Tue Apr 15 14:36:31 2008 : Auth: Login incorrect: [ew/bloccentre] 
(from client wlan-sen port 0)
Tue Apr 15 14:36:31 2008 : Debug:   TTLS: Got tunneled Access-Reject
Tue Apr 15 14:36:31 2008 : Debug:  rlm_eap: Handler failed in EAP/ttls
Tue Apr 15 14:36:31 2008 : Debug:   rlm_eap: Failed in EAP select
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[authenticate]: returned 
from eap (rlm_eap) for request 5
Tue Apr 15 14:36:31 2008 : Debug: ++[eap] returns invalid
Tue Apr 15 14:36:31 2008 : Debug: auth: Failed to validate the user.
Tue Apr 15 14:36:31 2008 : Auth: Login incorrect: [iti-adsl/<via 
Auth-Type = EAP>] (from client wlan-sen port 737 cli 000d.2885.af3e)
Tue Apr 15 14:36:31 2008 : Debug:   Found Post-Auth-Type Reject
Tue Apr 15 14:36:31 2008 : Debug: +- entering group REJECT
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[post-auth]: calling 
attr_filter.access_reject (rlm_attr_filter) for request 5
Tue Apr 15 14:36:31 2008 : Debug:     expand: %{User-Name} -> iti-adsl
Tue Apr 15 14:36:31 2008 : Debug:  attr_filter: Matched entry DEFAULT 
at line 11
Tue Apr 15 14:36:31 2008 : Debug:   modsingle[post-auth]: returned 
from attr_filter.access_reject (rlm_attr_filter) for request 5
Tue Apr 15 14:36:31 2008 : Debug: ++[attr_filter.access_reject] 
returns updated
Tue Apr 15 14:36:31 2008 : Debug: Delaying reject of request 5 for 1 
seconds
Tue Apr 15 14:36:31 2008 : Debug: Going to the next request
Tue Apr 15 14:36:31 2008 : Debug: Waking up in 0.9 seconds.
Tue Apr 15 14:36:32 2008 : Debug: Sending delayed reject for request 5
    EAP-Message = 0x04060004
    Message-Authenticator = 0x00000000000000000000000000000000
Tue Apr 15 14:36:32 2008 : Debug: Waking up in 0.5 seconds.
    User-Name = "000d2885af3e"
    User-Password = "000d2885af3e"
    Called-Station-Id = "001e.4a06.0650"
    Calling-Station-Id = "000d.2885.af3e"
    Cisco-AVPair = "ssid=adsl"
    Service-Type = Login-User
    NAS-Port-Type = Wireless-802.11
    Cisco-NAS-Port = "738"
    NAS-Port = 738
    NAS-IP-Address = 192.168.1.110
    NAS-Identifier = "wlan_sen_10"
Tue Apr 15 14:36:32 2008 : Debug: +- entering group authorize
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
preprocess (rlm_preprocess) for request 6
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from preprocess (rlm_preprocess) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[preprocess] returns ok
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 6
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from chap (rlm_chap) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[chap] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
mschap (rlm_mschap) for request 6
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from mschap (rlm_mschap) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[mschap] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
suffix (rlm_realm) for request 6
Tue Apr 15 14:36:32 2008 : Debug:     rlm_realm: No '@' in User-Name = 
"000d2885af3e", looking up realm NULL
Tue Apr 15 14:36:32 2008 : Debug:     rlm_realm: No such realm "NULL"
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from suffix (rlm_realm) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[suffix] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 6
Tue Apr 15 14:36:32 2008 : Debug:   rlm_eap: No EAP-Message, not doing EAP
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from eap (rlm_eap) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[eap] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling unix 
(rlm_unix) for request 6
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from unix (rlm_unix) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[unix] returns notfound
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
files (rlm_files) for request 6
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from files (rlm_files) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[files] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling sql 
(rlm_sql) for request 6
Tue Apr 15 14:36:32 2008 : Debug:     expand: %{User-Name} -> 000d2885af3e
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql (sql): sql_set_user escaped 
user --> '000d2885af3e'
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql (sql): Reserving sql socket 
id: 2
Tue Apr 15 14:36:32 2008 : Debug:     expand: SELECT id, username, 
attribute, value, op           FROM radcheck           WHERE username 
= '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, 
attribute, value, op           FROM radcheck           WHERE username 
= '000d2885af3e'           ORDER BY id
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql_mysql: query:  SELECT id, 
username, attribute, value, op           FROM radcheck           WHERE 
username = '000d2885af3e'           ORDER BY id
Tue Apr 15 14:36:32 2008 : Debug: WARNING: Found User-Password == "...".
Tue Apr 15 14:36:32 2008 : Debug: WARNING: Are you sure you don't mean 
Cleartext-Password?
Tue Apr 15 14:36:32 2008 : Debug: WARNING: See "man rlm_pap" for more 
information.
Tue Apr 15 14:36:32 2008 : Debug: WARNING: Found User-Password == "...".
Tue Apr 15 14:36:32 2008 : Debug: WARNING: Are you sure you don't mean 
Cleartext-Password?
Tue Apr 15 14:36:32 2008 : Debug: WARNING: See "man rlm_pap" for more 
information.
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql (sql): User found in 
radcheck table
Tue Apr 15 14:36:32 2008 : Debug:     expand: SELECT id, username, 
attribute, value, op           FROM radreply           WHERE username 
= '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, 
attribute, value, op           FROM radreply           WHERE username 
= '000d2885af3e'           ORDER BY id
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql_mysql: query:  SELECT id, 
username, attribute, value, op           FROM radreply           WHERE 
username = '000d2885af3e'           ORDER BY id
Tue Apr 15 14:36:32 2008 : Debug:     expand: SELECT 
groupname           FROM usergroup           WHERE username = 
'%{SQL-User-Name}'           ORDER BY priority -> SELECT 
groupname           FROM usergroup           WHERE username = 
'000d2885af3e'           ORDER BY priority
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql_mysql: query:  SELECT 
groupname           FROM usergroup           WHERE username = 
'000d2885af3e'           ORDER BY priority
Tue Apr 15 14:36:32 2008 : Debug:     expand: 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 -> SELECT 
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  
FROM radgroupcheck,usergroup WHERE usergroup.Username = '000d2885af3e' 
AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY 
radgroupcheck.id
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql_mysql: query:  SELECT 
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  
FROM radgroupcheck,usergroup WHERE usergroup.Username = '000d2885af3e' 
AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY 
radgroupcheck.id
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql (sql): User found in group wifi
Tue Apr 15 14:36:32 2008 : Debug:     expand: 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 -> SELECT 
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  
FROM radgroupreply,usergroup WHERE usergroup.Username = '000d2885af3e' 
AND usergroup.GroupName = radgroupreply.GroupName ORDER BY 
radgroupreply.id
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql_mysql: query:  SELECT 
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  
FROM radgroupreply,usergroup WHERE usergroup.Username = '000d2885af3e' 
AND usergroup.GroupName = radgroupreply.GroupName ORDER BY 
radgroupreply.id
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql (sql): Released sql socket id: 2
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from sql (rlm_sql) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[sql] returns ok
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
expiration (rlm_expiration) for request 6
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from expiration (rlm_expiration) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[expiration] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
logintime (rlm_logintime) for request 6
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from logintime (rlm_logintime) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[logintime] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling pap 
(rlm_pap) for request 6
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from pap (rlm_pap) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[pap] returns updated
Tue Apr 15 14:36:32 2008 : Debug:   rad_check_password:  Found Auth-Type
Tue Apr 15 14:36:32 2008 : Debug: 
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Apr 15 14:36:32 2008 : Debug: !!!    Replacing User-Password in 
config items with Cleartext-Password.     !!!
Tue Apr 15 14:36:32 2008 : Debug: 
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Apr 15 14:36:32 2008 : Debug: !!! Please update your configuration 
so that the "known good"               !!!
Tue Apr 15 14:36:32 2008 : Debug: !!! clear text password is in 
Cleartext-Password, and not in User-Password. !!!
Tue Apr 15 14:36:32 2008 : Debug: 
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Tue Apr 15 14:36:32 2008 : Debug: auth: type "PAP"
Tue Apr 15 14:36:32 2008 : Debug: +- entering group PAP
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authenticate]: calling 
pap (rlm_pap) for request 6
Tue Apr 15 14:36:32 2008 : Debug: rlm_pap: login attempt with password 
"000d2885af3e"
Tue Apr 15 14:36:32 2008 : Debug: rlm_pap: Using clear text password 
"000d2885af3e"
Tue Apr 15 14:36:32 2008 : Debug: rlm_pap: User authenticated successfully
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authenticate]: returned 
from pap (rlm_pap) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[pap] returns ok
Tue Apr 15 14:36:32 2008 : Auth: Login OK: [000d2885af3e/000d2885af3e] 
(from client wlan-sen port 738 cli 000d.2885.af3e)
Tue Apr 15 14:36:32 2008 : Debug: +- entering group post-auth
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[post-auth]: calling exec 
(rlm_exec) for request 6
Tue Apr 15 14:36:32 2008 : Debug: Exec-Program output:
Tue Apr 15 14:36:32 2008 : Debug: Exec-Program: returned: 0
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[post-auth]: returned 
from exec (rlm_exec) for request 6
Tue Apr 15 14:36:32 2008 : Debug: ++[exec] returns noop
Tue Apr 15 14:36:32 2008 : Debug: Finished request 6.
Tue Apr 15 14:36:32 2008 : Debug: Going to the next request
Tue Apr 15 14:36:32 2008 : Debug: Waking up in 0.2 seconds.
    User-Name = "iti-adsl"
    Framed-MTU = 1400
    Called-Station-Id = "001e.4a06.0650"
    Calling-Station-Id = "000d.2885.af3e"
    Cisco-AVPair = "ssid=adsl"
    Service-Type = Login-User
    Message-Authenticator = 0x35a1a659fe02b2e62f8cbd3e242992d2
    EAP-Message = 0x0201000d016974692d6164736c
    NAS-Port-Type = Wireless-802.11
    Cisco-NAS-Port = "738"
    NAS-Port = 738
    NAS-IP-Address = 192.168.1.110
    NAS-Identifier = "wlan_sen_10"
Tue Apr 15 14:36:32 2008 : Debug: +- entering group authorize
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
preprocess (rlm_preprocess) for request 7
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from preprocess (rlm_preprocess) for request 7
Tue Apr 15 14:36:32 2008 : Debug: ++[preprocess] returns ok
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling chap 
(rlm_chap) for request 7
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from chap (rlm_chap) for request 7
Tue Apr 15 14:36:32 2008 : Debug: ++[chap] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
mschap (rlm_mschap) for request 7
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from mschap (rlm_mschap) for request 7
Tue Apr 15 14:36:32 2008 : Debug: ++[mschap] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
suffix (rlm_realm) for request 7
Tue Apr 15 14:36:32 2008 : Debug:     rlm_realm: No '@' in User-Name = 
"iti-adsl", looking up realm NULL
Tue Apr 15 14:36:32 2008 : Debug:     rlm_realm: No such realm "NULL"
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from suffix (rlm_realm) for request 7
Tue Apr 15 14:36:32 2008 : Debug: ++[suffix] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling eap 
(rlm_eap) for request 7
Tue Apr 15 14:36:32 2008 : Debug:   rlm_eap: EAP packet type response 
id 1 length 13
Tue Apr 15 14:36:32 2008 : Debug:   rlm_eap: No EAP Start, assuming 
it's an on-going EAP conversation
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from eap (rlm_eap) for request 7
Tue Apr 15 14:36:32 2008 : Debug: ++[eap] returns updated
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling unix 
(rlm_unix) for request 7
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from unix (rlm_unix) for request 7
Tue Apr 15 14:36:32 2008 : Debug: ++[unix] returns notfound
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling 
files (rlm_files) for request 7
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: returned 
from files (rlm_files) for request 7
Tue Apr 15 14:36:32 2008 : Debug: ++[files] returns noop
Tue Apr 15 14:36:32 2008 : Debug:   modsingle[authorize]: calling sql 
(rlm_sql) for request 7
Tue Apr 15 14:36:32 2008 : Debug:     expand: %{User-Name} -> iti-adsl
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql (sql): sql_set_user escaped 
user --> 'iti-adsl'
Tue Apr 15 14:36:32 2008 : Debug: rlm_sql (sql): Reserving sql socket 
id: 1

Re: exec-program-wait problem with freeradius 2.0.3

Emmanuel Willems

Alan DeKok

tags

participants (2)