- Freeradius-Users - lists.freeradius.org

Re: exec-program-wait problem with freeradius 2.0.3
by Emmanuel Willems 16 Apr '08

16 Apr '08

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

2 1

eap
by xiningtom_1986 16 Apr '08

16 Apr '08

Hello!I want to know how to add a new eap type in freeradius!I expect your reply!Thank you!

3 4

rlm_detail and the processing of logs into SQL
by A.L.M.Buxey＠lboro.ac.uk 15 Apr '08

15 Apr '08

hi, we're using the detail method to put accounting packets into a file and then using the buffered-sql virtual server to then poll that file and periodically put it into a postgres database. however, we are hitting this little nastiness rlm_sql (sql) in sql_accounting: stop packet with zero session length. our NAS is sending a stop packet with a zero session length to the RADIUS server. at this point, the server gets stuck on this one and spends all its time complaining about this packet - this fills up the radiusd log very quickly (gigabytes of logs within hours) and the detail file is no longer processed. how can this be trivially tweaked so that this doesnt happen? in the database, acctsessiontime field is a bigint and is not enforced to be not null. alan

1 0

Virtual-Server attribute matching in users file.
by Matthew Schumacher 15 Apr '08

15 Apr '08

List, I'm getting some config together to implement virtual servers with freeradius 2.0.3 and I need to offer different attributes when the request comes from different servers. I see that there is a Virtual-Server internal attribute so I thought I could do something like this: DEFAULT Virtual-Server == 'dsl' Service-Type = Framed-User, Framed-Protocol = PPP, Framed-MTU = 1492 DEFAULT Virtual-Server == 'dialup' Service-Type = Framed-User, Framed-Protocol = PPP, Framed-MTU = 1500 However it's not working. I can see in the debug that it is using the 'dsl' server but I'm not getting any of the attributes. I can set it to use User-Name == 'validuser' and it matches and returns attributes just fine so I'm not thinking it's my config. Also, I'm noticing that the server returns attributes even when the access request is rejected. Anyone know why that is? Thanks, schu

2 2

Re: exec-program-wait problem with freeradius 2.0.3
by Emmanuel Willems 15 Apr '08

15 Apr '08

I added exec in post-auth in sites-enabled/default and sites-enabled/inner-tunnel and it's still no go. Did i miss something? Thankx, Emmanuel Alan DeKok wrote: > Emmanuel Willems wrote: >> > All works well in version 1.1.3 but the script does not get called in >> > version 2.0.3 > > List 'exec' in the "post-auth" section. > > Alan DeKok.

2 1

How do i change the NAS ip address
by johnson elangbam 15 Apr '08

15 Apr '08

hi, I've been configuring free radius 2.0.3, I've configured almost all the files and run successfully for the testing purpose from the localhost by using the "radtest", now I need to implement my radius in the real invironment by putting the NAS ip address, currently my NAS ip address is displayed as 127.0.0.1, I need to change this ip address. Please anybody tell how to change the NAS ip address. Thanks and Regards Elangbam Johnson

2 1

attributes lost
by Marc Boisis-Delavaud 15 Apr '08

15 Apr '08

Hello, When I authenticate in PEAP, my ldap attributes (ex Tunnel-Private- Group-Id) aren't send to the client, why ? Here is my debug: rlm_ldap: looking for reply items in directory... rlm_ldap: LDAP attribute radiusClass as RADIUS attribute Class = 0x4f553d61646d696e3b rlm_ldap: LDAP attribute radiusClass as RADIUS attribute Class = 0x4f553d61646d696e3b rlm_ldap: LDAP attribute radiusTunnelPrivateGroupId as RADIUS attribute Tunnel-Private-Group-Id:0 = "1" rlm_ldap: LDAP attribute radiusTunnelMediumType as RADIUS attribute Tunnel-Medium-Type:0 = IEEE-802 rlm_ldap: LDAP attribute radiusTunnelType as RADIUS attribute Tunnel- Type:0 = VLAN WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? rlm_ldap: user mdelavau authorized to use remote access rlm_ldap: ldap_release_conn: Release Id: 0 +++[ldap_prof] returns ok ++- group returns ok rad_check_password: Found Auth-Type EAP auth: type "EAP" +- entering group authenticate rlm_eap: Request found, released from the list rlm_eap: EAP/mschapv2 rlm_eap: processing type mschapv2 rlm_eap: Freeing handler ++[eap] returns ok +- entering group session expand: /opt/freeradius/radium/var/log/radius/radutmp -> /opt/ freeradius/radium/var/log/radius/radutmp expand: %{User-Name} -> mdelavau(a)univ-lr.fr ++[radutmp] returns ok Login OK: [mdelavau(a)univ-lr.fr/<via Auth-Type = EAP>] (from client heros59 port 0) +- entering group post-auth expand: /opt/freeradius/radium/var/log/radius/radacct/%{Client-IP- Address}/reply-detail-%Y%m%d -> /opt/freeradius/radium/var/log/radius/ radacct/10.14.0.59/reply-detail-20080414 rlm_detail: /opt/freeradius/radium/var/log/radius/radacct/%{Client-IP- Address}/reply-detail-%Y%m%d expands to /opt/freeradius/radium/var/log/ radius/radacct/10.14.0.59/reply-detail-20080414 expand: %t -> Mon Apr 14 10:04:29 2008 ++[reply_log] returns ok } # server inner-tunnel PEAP: Got tunneled reply RADIUS code 2 Class = 0x4f553d61646d696e3b Tunnel-Private-Group-Id:0 = "1" Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Type:0 = VLAN EAP-Message = 0x03090004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "mdelavau" PEAP: Processing from tunneled session code 0x730f30 2 Class = 0x4f553d61646d696e3b Tunnel-Private-Group-Id:0 = "1" Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Type:0 = VLAN EAP-Message = 0x03090004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "mdelavau" PEAP: Tunneled authentication was successful. rlm_eap_peap: SUCCESS ++[eap] returns handled Sending Access-Challenge of id 233 to 10.14.0.59 port 1645 EAP-Message = 0x010a002b1900170301002091080b47d0c51811b6674b7a649bd231e1f5fea643dd96b28362ea273fe51553 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xe5e74631eded5f77803ca60988c6d413 Finished request 22. Going to the next request Waking up in 4.6 seconds. rad_recv: Access-Request packet from host 10.14.0.59 port 1645, id=234, length=243 User-Name = "mdelavau(a)univ-lr.fr" Framed-MTU = 1400 Called-Station-Id = "0012.44bd.0b03" Calling-Station-Id = "0019.e304.476e" Cisco-AVPair = "ssid=eduroam" WISPr-Location-Name = "CRI Arpae" Service-Type = Authenticate-Only Message-Authenticator = 0x8cefe9357b38e5f0a52c291945837712 EAP-Message = 0x020a002b19001703010020dc122ffd1ad0290d995b344b65adbda0824e52829616cca6dfb590d9b510b732 NAS-Port-Type = Wireless-802.11 Cisco-NAS-Port = "36654" NAS-Port = 36654 State = 0xe5e74631eded5f77803ca60988c6d413 NAS-IP-Address = 10.14.0.59 NAS-Identifier = "heros59" +- entering group authorize ++[preprocess] returns ok ++[mschap] returns noop rlm_realm: Looking up realm "univ-lr.fr" for User-Name = "mdelavau(a)univ-lr.fr " rlm_realm: Found realm "univ-lr.fr" rlm_realm: Adding Stripped-User-Name = "mdelavau" rlm_realm: Proxying request from user mdelavau to realm univ-lr.fr rlm_realm: Adding Realm = "univ-lr.fr" rlm_realm: Authentication realm is LOCAL. ++[suffix] returns noop rlm_eap: EAP packet type response id 10 length 43 rlm_eap: Continuing tunnel setup. ++[eap] returns ok rad_check_password: Found Auth-Type EAP auth: type "EAP" +- entering group authenticate rlm_eap: Request found, released from the list rlm_eap: EAP/peap rlm_eap: processing type peap rlm_eap_peap: Authenticate rlm_eap_tls: processing TLS eaptls_verify returned 7 rlm_eap_tls: Done initial handshake eaptls_process returned 7 rlm_eap_peap: EAPTLS_OK rlm_eap_peap: Session established. Decoding tunneled attributes. rlm_eap_peap: Received EAP-TLV response. rlm_eap_peap: Success rlm_eap: Freeing handler ++[eap] returns ok Login OK: [mdelavau(a)univ-lr.fr/<via Auth-Type = EAP>] (from client heros59 port 36654 cli 0019.e304.476e) +- entering group post-auth ++[exec] returns noop Sending Access-Accept of id 234 to 10.14.0.59 port 1645 MS-MPPE-Recv-Key = 0xbf9d41342546813406854e35cabdf79521b33e2c316aff8d599716484cc18c20 MS-MPPE-Send-Key = 0xaff6c3d06041e693b8acb1067d382699f150da706b799e4960ab82be1f25a96a EAP-Message = 0x030a0004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "mdelavau"

4 7

radiusd not starting
by Dr.Peer-Joachim Koch 15 Apr '08

15 Apr '08

Hi, we updated yesterday one of our server running Novell SLES 9. After the update the "raidusd" (not the sles version, self compiled) did not work correctly (the load was getting higher and higher). Therefore I installed the current version of the freeradius-server (2.0.3) from http://download.opensuse.org/repositories/network:/aaa/ After fixing a few things in the /etd/raddb/users the server is running fine, when I do a radiusd -X also radius -f seem's to work. But neither a radiusd not /etc/init.d/freeradius start is launching the radiusd-Daemon. But I can not see WHY the raidusd is not starting as daemon. Any idea ? -- Bye, Peer _________________________________________________________ Max-Planck-Institut fuer Biogeochemie Dr. Peer-Joachim Koch Hans-Knöll Str.10 Telefon: ++49 3641 57-6705 D-07745 Jena Telefax: ++49 3641 57-7705

2 2

Freeradius support IAPP (IEEE 802.11f)?
by Yeray Domínguez 14 Apr '08

14 Apr '08

Hello. I'm doing a tutorial of the RADIUS, IAPP and EAP protocols. I've had using FreeRADIUS to explain the practice part of the tutorial. But I don't know if FreeRADIUS support IAPP. Please, it's very important for me to know it. If the response is 'no', could you recommend me another RADIUS server that support IAPP? Thanks. ______________________________________________ Tu correo también desde el móvil. Descárgate gratis Yahoo! Go. http://es.mobile.yahoo.com

2 1

Proxy request after TLS.
by Andrew Olson 14 Apr '08

14 Apr '08

I'd like to proxy a request to another server after the EAP-TLS handshake is finished. I simply want to do a little more authorization that is already setup on another server. My other server is just a simple RADIUS server and doesn't do EAP, so proxying the EAP message won't work. I guess I'm looking for something like proxy-inner-tunnel configuration that is available for PEAP. Is something like this possible? I tried to add the following block to post-auth: update control { FreeRadius-Proxied-To := blah } It returns noop, though. Thanks, Andrew Olson

2 3