exec-program-wait problem with freeradius 2.0.3
Emmanuel Willems
ew at senate.be
Wed Apr 16 09:53:17 CEST 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 at 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
More information about the Freeradius-Users
mailing list